Sturgeon's Law and Context Sensitivity

Hi. My name is Chip, and I've been a manager. More than once. It's not something I'm proud of, nor did I find those experiences personally fulfilling, and only rarely enjoyable. Some misguided folks seemed to think I was good at it. It was an opinion I myself didn't share.

But I tried to be the best manager I could be, and part of that effort was spent reading books that made the bestseller lists in the various business magazines. Over the years I came to the conclusion that, like pretty much everything else, business books obey Sturgeon's Law:"Ninety percent of everything is crap" [1].

An article by Matthew Stewart, "The Management Myth", published in 2006 in the magazine The Atlantic (and also as a book reviewed in the Wall Street Journal), speaks to this. In it, Stewart relates how he spent seven years as a management consultant, ultimately co-founding a management consulting firm that employed six hundred people. Stewart did not have an M.B.A. He didn't have a business degree at all. He had a Ph.D. in nineteenth-century German philosophy. So, was he a natural born genius in business management? Not so much. To hear him tell the tale, he pretty much faked it. He doesn't make it sound that hard. He also runs to ground many of the classic epic tales in management, many of which I'd read or been told about during my own management training, revealing many to have actually been epic fails.

Frederick Winslow Taylor is credited with creating management as a profession by writing the book The Principles of Scientific Management based on his experience with figuring out in 1899 how to get laborers to load train cars faster: he bribed them. His book however described a much more complicated theory of management, which some called "Taylorism", which could only be accomplished by someone with an advanced education, an expensive suit, and for sure a higher salary. Unfortunately, it was a theory whose application could not be replicated by others. Bethlehem Steel Company eventually wised up, fired him, and scrapped his new fangled management techniques.

Another anecdote, and one that I had also heard about before, involved Homer Hibarger, who in the early twentieth century was doing research into how to increase productivity of workers by increasing workplace illumination. Since this research was being funded by a manufacturer of electric light bulbs, you may assume the results were a forgone conclusion, for otherwise they would have never, ah, seen the light of day. Indeed, productivity among a group of woman on a assembly line at a Western Electric plant increased when the illumination of the work area was increased. It also improved when illumination was decreased. In fact, productivity increased when almost any change was made in the work environment. What change resulted in the greatest improvement? Apparently, that occurred when some of the women on the line were replaced with others who were easier to get along with. And the fact that the women earned extra compensation for participating in the experiment.

Stewart isn't shy about relating his own experiences as a management consultant, watching his fellow consultants massage raw data to fit the curve that they needed, altering conclusions to match those required by their client, or reiterating the latest fad from a recent business bestseller whether it was applicable to the situation or not. Eventually his disillusionment led him to leave his consulting firm, only to watch it self-destruct in the receding distance under the squabbles of the remaining partners.

I had a similar period of disillusionment as a manager. I was a fan the 1982 bestseller In Search of Excellence by Tom Peters and Robert Waterman. It had what appeared to be hard data on how companies succeeded in their industries through both innovation and good management. That list of excellent companies included 3M, Walt Disney, and Intel. And also Amdahl, Data General, and Wang Laboratories. As I read other books by Tom Peters, I began to see less and less hard data from Peters backing up whatever management fad he was pushing. And about those excellent companies: many of them later fell on hard times, and some of them ceased to exist all together. Some, like NCR and Xerox, didn't even produce great financial results at the time the book was published. Peters was later accused of fudging the data for the book, a charge he denies.

But I'm reluctant to be too hard on Peters, or for that matter on Hibarger or even Taylor. Because although I'm a lousy manager, I have a pretty good track record as a software developer. And one thing I've learned over the past three-plus decades from studying, applying, and being painfully subjected to the latest software development process fad: the application of all processes and techniques, regardless of the problem domain, is very sensitive to context.

Extreme Programming was widely publicized before it had ever had its first big success. It was first applied to a project at Chrysler which never came to fruition; the project was cancelled when Chrysler was acquired by Daimler-Benz. Large development organizations (like the kind I have found myself in much of my career) have found the principles of Agile Development difficult to apply to non-co-located staff or to mission critical applications (ditto). The U.S. government (as well as many large development organizations) have found the classic Waterfall Process to be way too heavy-weight and inefficient to work at the rapidly changing pace of software development, although it works for things like building nuclear submarines.

That doesn't mean that Peter's eight themes of excellent companies, Boehm's tenets of Extreme Programming, the principles of the Agile Manifesto, or even the hoary old Waterfall Process, are fundamentally wrong. On the contrary, all of those have nuggets of great truths in them. It just means any particular technique or process can't be all things to all people all the time. Expecting any of them to work in all circumstances is just plain naive. And that includes whatever article on the latest thing in business management or software development that you are reading today. You might even apply Sturgeon's Law to mean that any of these ideas will be applicable at most 10% of the time.

Besides, it is in dealing with the exceptions where managers, and developers, earn their pay. The exceptions are what require innovation, insight, experience, and improvisation. As much as upper management would like to have a recipe for guaranteed success, sometimes you just have to make it up as you go long. And to come back to Stewart's article in The Atlantic, it's almost always more about the people you have than the process you use.

If it were easy, anybody could do it.

(Many thanks to my old friend and occasional colleague Jacque Marshall for passing the Stewart article along.)

[1] I was fortunate many years ago to hear the late Theodore Sturgeon relate this anecdote in person: at a dinner party a woman asked what he did for a living. "I'm a science fiction writer," he replied. "Oh dear," she said, "isn't ninety percent of it crap?" "Yes", he explained, "but ninety percent of everything is crap."

Elisabeth Sladen, a.k.a. Sarah Jane Smith, Dead of Cancer at 63

This is being reported by the BBC.

http://www.bbc.co.uk/news/entertainment-arts-13137674

The SF media blog io9 has a warm and sentimental obituary.

http://io9.com/#!5793664/rip-elisabeth-sladen-doctor-whos-apprentice

Thanks to forsinain42 for this.

"Pain and loss define us as much as happiness or love. Whether it’s a world or a relationship… Everything has its time and everything ends."

Sarah Jane Smith
Doctor Who: Series 2 - School Reunion

I am crying at my desk.

Deconstructing the AR.drone: Part 6

The other day the Free Flight app on my iPad told me that there was a new firmware release available for my AR.drone. I figured there was no better time to try loading new firmware using the diagnostic port on the bottom of the device.

Here is the bottom of my drone with the rubber plug with the USB symbol on it removed. You can see the port just to the lower left of center, and you can see the missing indexing pin of the eight-pin header in the upper left of the port.

Here's what I needed:

• a cable I built that has a USB Type A connector on one end and an eight-pin Molex connector on the other, wired up as described on the AR.drone reference platform web site;
• the AR.drone tools developed by user skorpion2k, which include the libplf library, the plf_inst_extract tool, and the usb_flash tool, the latter which includes the USB driver needed by the process;
• a copy of the USB boot loader ardrone_usb_bootloader.zip kindly provided by user MAPGPS on the RC Groups web site;
• a copy of the latest AR.drone firmware update file ardrone_update.plf from Parrot;
• a Windows system with the usual accoutrements.

Here's the cable I fabricated, with the eight-pin Molex connector on the left and the Type A USB connector on the right. You can see the blocked socket that will match the missing indexing pin on the port when the cable is inserted in the correct orientation.

Here's the diagram of the cable that was provided by Parrot.

I unloaded all of the AR.drone tool zip files into separate directories on my Windows laptop so that the README files wouldn't overwrite one another, but consolidated all of the sub-directories, dynamic link libraries, and executables, plus the ardrone_usb_bootloader.zip file, into a single directory. There was a drivers sub-directory with the P6_USB_Stage1 device driver.

I used the plf_inst_extract tool to extract the ardrone_installer.plf file from the ardrone_update.plf file. The README file that comes with the usb_flash tool says to use a command like this

plf_inst_extract -i ardrone_update.plf -o ardrone_installer.plf

but as usual I am incapable of following simple instructions. Here's a screen shot.

I omitted the -o ardrone_installer.plf option. The plf_inst_extract tool uses the name extract_installer.plf by default, but the usb_flash tool expects it to be named ardrone_installer.plf. So I renamed it. Here's what was in the directory after doing that.

The order of these next steps is important. I connected my laptop to the unpowered drone using the cable that I had made. The diagnostic LED on the bottom of the drone lit up as a portion of the digital logic in the drone was powered from the USB cable itself. Then I connected the drone to its battery. The USB interface in the drone enumerated on my laptop. I went through the Windows device driver installation dialog to point it to the drivers subdirectory of the AR.drone tools. Windows installed the P6_USB_Stage1 driver. Here's a screen snapshot of the Windows Device Manager following that process.

I ran the usb_flash tool without any arguments at all. The first time it failed to establish contact with the drone, probably because I botched the order of something, but it worked fine the second time. Here's the successful run split into two screen snapshots.

I disconnected everything, cycled power on the AR.drone, connected my iPad to it, and the Free Flight app reported that the drone was running the new version of firmware.

This is a great example of how this kind of hacking depends upon the kindness of strangers. From the wiring diagram provided by the AR.drone's manufacturer Parrot, to the software tools developed and provided by skorpion2k, to the boot loader binary provided by MAPGPS, it is a combined effort of an avid community of AR.drone enthusiasts.

Deconstructing the AR.drone: Part 5

In this article I will describe some of the tools I've been using in my quest to understand the AR.drone. Some of them I had to build myself; that's part of the fun.

When it's engines aren't rotating, the 11.1 volt AR.drone battery lasts considerably longer than the nine to twelve minutes of flight time you typically get. But I wanted to spend as much time as necessary poking around in the drone's software without having to worry about losing power. Unable to find the battery connector locally, I bought the cheapest used battery I could find off EBay, snipped the connector off of it, and attached it to a 12V power supply I got from Radio Shack.

Important safety tip: I probably voided the warranty on my drone as soon as I hooked it up. But it seemed to work fine and it permitted me to work at a much more leisurely pace. If I'd had an expensive lab bench-quality power supply, I probably would have used that instead.

The AR.drone has an eight-pin (one pin missing) diagnostic connector accessible from its underside, covered with a rubber plug with a USB symbol on it. This shows my drone lying upside down with the plug removed and a logic analyzer hooked up to three of the pins.

Important safety tip: the AR.drone really doesn't like sitting at much of an angle and its software will complain bitterly and eventually refuse to do useful things. But placing it upside down was relevant to my interests.

This is Parrot's diagram describing the USB cable you can build that allows you to flash new software onto your drone without relying on the wireless network connection. What this diagram doesn't tell you is that pins 4 and 6, shown unconnected here, are receive data (a.k.a. RX, RD, RXD) and transmit data (a.k.a. TX, TD, TXD) respectively for a TTL-level serial port right off the drone's microprocessor. Pin 7 is ground just as with the USB cable. This serial port is configured to be a console terminal for the system.

Important safety tip: the serial port pins are transistor-transistor-logic (TTL) level, which on the drone's ARM-based Parrot P6 processor means something like zero to 3.3 volts. RS-232 peak signal levels vary widely, but logic values can range from -15 to 15 volts, and the standard requires that hardware tolerate voltages as high as 25 volts. Standard compliant RS-232 ports will not recognize the input signal levels of the drone's serial port, and peak RS-232 output voltages may damage the microprocessor in the drone. More on this below.

This is the USB flash cable I fabricated using the Parrot cable diagram above. I just bought a USB cable at Radio Shack, hunted down another cable that had the right eight-pin Molex connector on it, snipped the ends off both cables and did a bit of soldering. I've successfully used this cable, and some software tools developed by others, to flash my drone with the latest drone software from Parrot. I'll describe that process in a later article.

This is a DB9 null-modem serial cable that I fabricated using the same approach as the USB cable, using the transmit and receive pins and the same ground pin as the USB cable. After using these cables for a bit it occurred to me that an even better approach would have been to build a single Y-cable with a the eight-pin Molex connector on one end and both a DB9 and a USB cable on the other end. That would have given me console access while reflashing my drone.

This is a commercially available USB to 3.3 volt TTL DB9 adaptor that uses an IC from Future Technology Devices International, Limited (FTDI). It automatically does the conversion from the TTL signal level to USB serial. Otherwise it works just like any other USB serial adaptor.

This is not my first experience with FTDI products, and it won't be the last; I'm an FTDI fanboy. This cable uses one of their ICs embedded in the DB9 hood. This same or similar FTDI chip can be surface mounted in a embedded application. This is a huge win. First, you can use one of the mini or micro USB B connectors, which have a tiny footprint compared to other serial connector alternatives, as a console port for your application. Second, USB cables with the right connectors are easier to come by these days than serial cables, and it is impossible to hook them up wrong. Third and most importantly, the FTDI chip is powered not from your embedded application, but over the USB cable from your laptop or desktop; this means it doesn't draw power when it's not being used, and it's active and running long before your microprocessor comes out of reset and the boot loader configures and starts using the serial port. (A big Thank You to my hardware colleagues for introducing me to this.)

Important safety tip: this is the third such device I've tried on the AR.drone, and is the only one that has worked, which it did flawlessly. The others, made by companies I'd never heard of, were crap. (This is in fact the reason for the long pause between articles on this project.)

It may sound like overkill, but I used a logic analyzer to make sure I had the pins right on the serial console port. But at around US$150 for an eight channel logic analyzer, that you can fit in your laptop bag, with a 24MHz sampling rate and serial decoders, doing so was kind of a no-brainer. I used a Saleae Logic, one of many USB-connected logic analyzer pods and software packages used in conjunction with a laptop. This is the Logic pod hooked up to my little HP 110 Mini netbook running the Logic software.

Here is the nice zippered case (complete with cat hair, I now notice) that the Logic comes in, and its contents, along with my little key ring pocket knife just for scale. The Logic pod is about one inch or so square and is shown here with a company property sticker on it that almost covers the entire unit.

This is a screen snapshot of the actual hexadecimal serial decode when the Logic was hooked up to the AR.drone while the drone was booting. It captured part of a "BMI Write Memory" message.

When you're building cables it pays to check voltages and continuity before committing yourself to your soldering. I use a Radio Shack digital multimeter. It's probably the slowest reading digital multimeter I've ever used. But it's also a fraction of the price of the nice lab bench-quality units I've used in the past, and otherwise seems to work fine.

If you're going to solder, particularly if you're going to solder digital components (as I did when adding an expansion connector to my Beagle Board), a quality soldering iron is an absolute must. And it'll make cables too. This is a Weller WESD51 Digital Soldering Station with digital temperature control. I really like the fact that I can just dial in the recommended soldering temperature right from the manufacturer's data sheet, and the unit heats up in seconds.

This is a Weller 6966C 250 Watt Industrial Heat Gun. It's overkill for use on shrink wrap when making cables. But it's ESD safe and gets hot enough to melt solder, so it is not one of Alton Brown's dreaded uni-taskers. Alton would also use it to brown the top of Creme Brulee.

There are also some tools in my AR.drone arsenal that I haven't quite needed yet, or which are more in the experimental stages.

Parrot sells a small tool kit with the specialized parts necessary to take the AR.drone apart and to replace parts like the propellers likely to be damaged during normal use. I'll be using these when I follow in other's footsteps and open the drone up to take a closer look at its digital components.

For sure when I open the AR.drone up I'll be using a grounded Electro-Static Discharge (ESD) or anti-static mat and wrist strap. I have a permanent one wired up on the computer desk where I do most of my poking around (you can see it in some of my other articles). But I like to keep this fold-up field service model in my big tool kit.

In one of my more speculative side-projects, I'm experimenting with how the AR.drone uses its ventral camera to stabilize itself during hovering. Consensus opinion on the web is that it is using edge detection, so I am using a vinyl checker board as a high contrast take off pad. Others have suggested that sometimes the drone has problems seeing the take off pad in dim light, so I'm trying to illuminate it with a tiny button cell-powered flashlight whose LED emits in the infrared (IR). Finally, I'm using an IR night vision viewer to see the LED myself; remarkably, this viewer can be found in your local toy store. You may also be surprised to find, as I did, how many LEDs in objects around the house emit in the IR portion of the spectrum.

Next up: I describe how I flashed new software into my AR.drone over its diagnostic port via the USB cable by depending upon the kindness of strangers.

The House of Cards

I cannot say that I am especially a fan of the horror fiction genre. But I am a total fanboy of the non-fiction work of Eric Eide and John Regehr and their team at the University of Utah School of Computing. In 2008 they published a paper

Eric Eide and John Regehr, "Volatiles are miscompiled and what to do about it", Proceedings of the 8th ACM International Conference on Embedded Software, 2008-10

which scared the crap out of me.

They developed a tool called randprog to see how a broad set of open source and commercial C compilers handled the volatile keyword. volatile is used to clue in the compiler that the declared variable might change outside of the context of the program. It is most typically used for variables that represent hardware registers that are mapped into memory.

The results were... interesting, to say the least. They found many many examples where the use of volatile was miscompiled. One of the tricks they suggested to get around a buggy compiler was to embed the use of a volatile variable inside accessor (getter) and mutator (setter) functions; the semantics of function parameters and return values are similar to those of volatile, and the code paths in compilers to handle those idioms are much more heavily travelled and hence more mature and bug free.

If, like me, you make a good living writing code down near the bare metal, perhaps even code upon which lives depend, a better description than interesting might be terrifying. But not terribly surprising.

You might think that volatile would be useful in multithreaded programs, where, indeed, shared variables can change outside of the context of the code the compiler can see in a particular translation unit. But the experience in the community of developers that write real-time, embedded, and/or highly concurrent code has been so bad that the use of volatile is highly discouraged.

If you look under the Documentation directory of any fairly recent Linux kernel (I have six from which to choose on my build server), you will find the file volatile-considered-harmful.txt. The file name should give you a clue where this is heading. In that file is an article

Jonathan Corbet, Why the "volatile" type class should not be used, Linux kernel documentation

which states that, regarding Linux kernel development, "the use of volatile is likely to be seen as a bug and will bring additional scrutiny to the code". This isn't because volatile doesn't work. It's because the optimization suppressing characteristics of volatile are seldom what is really required, except in certain very narrow circumstances, which do not include variables shared between concurrent sections of kernel code.

Outside of the kernel, where application developers are increasingly developing highly concurrent (a.k.a. multithreaded) code to leverage multi-core platforms, volatile in C and C++ code is also problematic. The memory models implemented at the hardware level by memory subsystems, which neither know nor care about whether you declared a shared variable in your high-level source code on some far off server to be volatile, frequently defeat what you intended to convey by the use of the keyword.

For example, in section 6.4.2, "Atomicity Operations", of the lengthy but entirely worthy tome

Ulrich Drepper, What Every Programmer Should Know About Memory, Red Hat Inc., 2007-11-21

the author discusses the MESI cache coherency protocol as commonly implemented in the memory subsystems of the processors you are using today.

If multiple threads modify the same memory location concurrently, processors do not guarantee any specific result. This is a deliberate decision made to avoid costs which are unnecessary in 99.999% of all cases. For instance, if a memory location is in the ‘S’ state and two threads concurrently have to increment its value, the execution pipeline does not have to wait for the cache line to be available in the ‘E’ state before reading the old value from the cache to perform the addition. Instead it reads the value currently in the cache and, once the cache line is available in state ‘E’, the new value is written back. The result is not as expected if the two cache reads in the two threads happen simultaneously; one addition will be lost.

As a result, libraries that implement threading for C and C++, like POSIX threads, handle shared variables by using a combination of arcane compiler-specific directives that are not part of the programming language, and equally arcane processor instructions that implement memory barriers that keep the memory subsystem from doing something stupid.

The downside is that these mechanisms frequently effect all of the memory in the application, or even in the entire processor, not just the one shared variable with which the developer was concerned. This has been cogently discussed in

Sarita V. Adve and Hans-J. Boehm, "Memory Models: A Case for Rethinking Parallel Languages and Hardware", Communications of the ACM, 53.8, 2010-08

as well as in other forums.

You Java developers out there, don't get smug. You would do well to read

David Bacon et al., The "Double-Checked Locking Is Broken" Declaration

and come to understand what violence has been done to your Java compiler and Java Runtime Environment in order to fix this so that you could remain blissfully unaware of what's going on under the hood while your code runs slower albeit correctly. The same fixes applied by implementations of POSIX threads for C and C++ were applied to Java and the JRE.

But the fun doesn't stop there.

In

Xuejun Yang, Yang Chen, Eric Eide, John Regehr, "Finding and Understanding Bugs in C Compilers", Proceedings of the 2011 ACM SIGPLAN Conference on Programming Language Design and Implementation, 2011-06

my heros are back with a new random C code generator, Csmith, that is able to similarly test their collection of C compilers for misbehavior beyond just volatile. And they found that C compilers do aim to misbehave.

Csmith randomly generates legal C programs within a set of constraints that avoids producing code that strays into areas that the ANSI C standard defines as, well, undefined. They compile this code with their menagerie of C compilers. If the compilers don't crash and do produce an executable program (they don't always, as it turns out), they run all of the executables and see if they all produce the same answer. This process is automated so that they can test a million little C programs across many compilers.

They characterize most compiler optimizer implementations with this pseudo code snippet

analysis
if (safety check) {
 transformation
}

and observed the "most common root cause for bugs that we found was an incorrect safety check". But their paper cites plenty of examples of wrong analysis and wrong transformation as well.

What's more, when they do misbehave, they do so in different, unrelated ways: "Csmith has yielded no evidence of correlated failures among unrelated C compilers".

Has Csmith been successful? "So far we have reported 79 GCC bugs and 202 LLVM bugs"; "To date, we have reported 325 in total across all tested compilers"; "twenty-five of the GCC bugs were marked by developers as P1: the maximum, release-blocking priority".

Where have the bugs been? "Most of the bugs we found in GCC were in the middle end: the machine-independent optimizers".

Are the bugs that Csmith is finding important? Aside from the GCC developers own classification of some of the bugs as release-blocking, "bugs that we have found and reported have been independently rediscovered and re-reported by application developers". What has been observed in captivity has also been observed in the wild.

Is Csmith a cost effective way of finding bugs? "Our rough estimate ... is that each of the more than 325 bugs we reported costs less than $1000 to find". That's a remarkably cost effective tool when you consider how many hours of the fully-loaded cost of a software developer that amount of money would buy.

Whenever I am tempted to think I've run into a compiler bug, I assume I'm really experiencing a senior moment and simply don't understand my own code. Nearly all the time, that's the case. But not always. I have occasionally resorted to scrutinizing assembly output to debug my code, and have rarely encountered what was clearly a compiler misstep. For example, decades ago I caught a compiler reusing a register for an arithmetic calculation then blithely returning to using the register as a pointer to a structure. Wackiness ensued. Try code inspecting or unit testing your way out of that one.

But it's not when a compiler bug causes my software to crash, as it did in that example, that I'm the most concerned about. It's when it doesn't crash. Applying automated bug extermination to our tool chains sound to me like a good addition to the arsenal in defense of reliable software.

Deconstructing the AR.drone: Part 4

A typical approach to debugging a product in the lab and supporting it in the field is to log messages emitted by the software. Log messages might be saved to some persistent medium in the product itself, transmitted across a network to some log server, or simply displayed on a serial port where they are lost if no one is watching.

Logging isn't always the best mechanism. But it is so common that every project I've ever worked on of any size had some formal mechanism for logging messages: Apache has log4j, the Java Runtime Environment has java.util.logging, and most UNIXen including GNU/Linux have the system log or syslog, and other systems have at least had a proprietary or roll-your-own logging mechanism. All of these had some way to classify messages according to their severity, ranging from apocalyptic to of interest only to some developer you don't know and will never meet, and usually some mechanism to quench the potential fire hose of messages by selectively enable or disabling different classifications.

The UNIX system log mechanism is so widely used that there are implementations of it for other operating systems; long ago I used one on Windows NT. Many (but not all) implementations support features like forwarding log messages across a network, aggregating log messages received across a network from many sources, and automatically rotating log files based on some criteria typically based on time or space or upon demand. Messages are logged using the syslog(3) function. Long-running applications, particularly those that run devoid of any attached terminal, like daemons, log all their output using this function. Log messages are transmitted to the system log daemon, typically called something like syslogd, which stores, forwards, or discards them according to its configuration.

The system log API allows messages to be classified into eight different severity levels: emergency, alert, critical, error, warning, notice, informational, and debugging. It also allows them to be orthogonally classified into a variety of facilities, such as daemon, security/authorization, or user. (Admittedly, some of the supported facilities, like UUCP and USENET News, reflect the mechanism's ancient heritage.) Messages are time stamped, and can even be identified according to their point of origin in a network. The default location for the current system log file is /var/log/messages.

Just to make matters more complicated, the Linux kernel and its device drivers do not directly use the system log. The system log API a user-space mechanism. Software living in kernel-space have their own logging mechanism that stresses low latency and non-blocking, because of the real-time nature of the kernel and device drivers, and because the kernel must be able to log messages very early in the boot process before any daemons like syslogd are running.

Kernel-space provides the printk() function and its derivatives like pr_debug() and pr_err(). Kernel-space log messages are written into a memory-resident ring buffer. There is yet another daemon, typically named klogd, that reads this buffer, using a mechanism like /proc/kmsg, as quickly as a user-space process can, and dumps the messages it finds there to the system log. (Some implementations of the system log daemon can actually do this.)

The kernel log daemon can't always keep up, so the ring buffer may overflow. And it doesn't even run until the system is mostly completely up and running. So kernel developers may depend on other mechanisms, including hardware debuggers, to read the ring buffer directly out of memory. On embedded Linux systems I have developed, the location of the ring buffer can be found in the System.map kernel link map under the name __log_buf.

Writing good system log messages is more of an art than a science, and there is some legitimate disagreement among even the most elite developers about how best it is done. Indeed, the correct technique is probably context sensitive. But even so, if, like me, you are often called upon to debug complex embedded, real-time, and distributed systems, you would frequently kill for a good log messages indicting a particular component or at least yielding a useful clue.

So at least we come to the AR.drone, which has a /var/log/messages file to which messages are persistently stored. Below is an example system log from my AR.drone. This is long, and made longer by the fact that I will provide some post-message annotation as to what I find interesting. Without the source code for the proprietary portions of the drone software, much of this will be speculation. (Warning: Blogger is not the best editor at dealing with code and pre-formatted text. I have also stripped the time stamp and other standard prefix information off each message to get more on the screen. It will get ugly.)

syslogd started: BusyBox v1.14.0
klogd started: BusyBox v1.14.0 (2011-02-04 10:06:10 CET)

No big surprise: on this system, the system log daemon and the kernel log daemon are both implemented in BusyBox, the swiss army knife of embedded software.

p6 mux select pin @0xfd000068 : 0x55555655->0x45555655
p6 mux select pin @0xfd000068 : 0x45555655->0x05555655
p6 mux select pin @0xfd000064 : 0x55555055->0x55556055
p6 mux select pin @0xfd000064 : 0x55556055->0x5555a055
p6 mux select pin @0xfd000070 : 0x55555555->0x55554555
p6 mux select pin @0xfd000070 : 0x55554555->0x55550555
p6 mux select pin @0xfd000070 : 0x55550555->0x55540555
p6 mux select pin @0xfd000070 : 0x55540555->0x55500555
p6 mux select pin @0xfd000070 : 0x55500555->0x55400555
p6 mux select pin @0xfd000070 : 0x55400555->0x55000555
p6 mux select pin @0xfd000070 : 0x55000555->0x54000555
p6 mux select pin @0xfd000070 : 0x54000555->0x50000555
p6 mux select pin @0xfd000070 : 0x50000555->0x40000555
p6 mux select pin @0xfd000070 : 0x40000555->0x00000555
p6 mux select pin @0xfd000074 : 0x15555555->0x15555554
p6 mux select pin @0xfd000074 : 0x15555554->0x15555550
p6 mux select pin @0xfd000074 : 0x15555550->0x15555540
p6 mux select pin @0xfd000064 : 0x5555a055->0x5554a055
p6 mux select pin @0xfd000064 : 0x5554a055->0x5550a055
p6 mux select pin @0xfd000064 : 0x5550a055->0x5540a055
p6 mux select pin @0xfd000064 : 0x5540a055->0x5500a055
p6 mux select pin @0xfd000064 : 0x5500a055->0x5400a055
p6 mux select pin @0xfd000064 : 0x5400a055->0x5000a055
p6 mux select pin @0xfd000064 : 0x5000a055->0x4000a055
p6 mux select pin @0xfd000064 : 0x4000a055->0x0000a055
p6 mux select pin @0xfd000068 : 0x05555655->0x05555654
p6 mux select pin @0xfd000068 : 0x05555654->0x05555650
p6 mux select pin @0xfd000068 : 0x05555650->0x05555640
p6 mux select pin @0xfd00005c : 0x55755555->0x5575d555
p6 mux select pin @0xfd00005c : 0x5575d555->0x5575f555
p6 mux select pin @0xfd00005c : 0x5575f555->0x5577f555
p6 mux select pin @0xfd000060 : 0x55555555->0x55755555
p6 mux select pin @0xfd000060 : 0x55755555->0x55f55555
p6 mux select pin @0xfd000060 : 0x55f55555->0x57f55555
p6 mux select pin @0xfd000060 : 0x57f55555->0x5ff55555
p6 mux select pin @0xfd000060 : 0x5ff55555->0x7ff55555
p6 mux select pin @0xfd000060 : 0x7ff55555->0xfff55555
p6 mux select pin @0xfd000064 : 0x0000a055->0x0000a057
p6 mux select pin @0xfd000064 : 0x0000a057->0x0000a05f
p6 mux select pin @0xfd00005c : 0x5577f555->0x5577f554
p6 mux select pin @0xfd00005c : 0x5577f554->0x5577f550
p6 mux select pin @0xfd00005c : 0x5577f550->0x5577f540
p6 mux select pin @0xfd00005c : 0x5577f540->0x5577f500
p6 mux select pin @0xfd00005c : 0x5577f500->0x5577f400
p6 mux select pin @0xfd00005c : 0x5577f400->0x5577f000
p6 mux select pin @0xfd00006c : 0x55555005->0x55554005
p6 mux select pin @0xfd00006c : 0x55554005->0x55550005
ethernet is on jtag
gpio 34 is not selected.
Please do it in your board code
p6 mux select pin @0xfd000058 : 0x55500000->0x55500010

I'm guessing this is the software configuring the System On a Chip (SoC) as to what pins are used for what I/O controllers. SoCs typically overload the pins on the chip and allow the software to configure different pins for different uses. For example, a particular set of three pins might be configurable as either a serial port or as individually programmable General Purpose I/O (GPIO) pins.

ARM PL08x DMA controller driver $Revision: 1.3 $
SCSI subsystem initialized
usbcore: registered new interface driver usbfs
usbcore: registered new interface driver hub
usbcore: registered new device driver usb

USB mass storage devices emulate the Small Computer System Interface (SCSI) standard originally developed for devices like disk drives.

NET: Registered protocol family 2
IP route cache hash table entries: 1024 (order: 0, 4096 bytes)
TCP established hash table entries: 4096 (order: 3, 32768 bytes)
TCP bind hash table entries: 4096 (order: 2, 16384 bytes)
TCP: Hash tables configured (established 4096 bind 4096)
TCP reno registered
NET: Registered protocol family 1

These are typical messages from the Internet Protocol stack as it initializes.

P6 Watchdog driver loaded default (30 seconds)

Most embedded systems have some kind of hardware watchdog: a device that autonomously resets the system if it is not "petted" by software periodically, in a last ditch effort to recover from a hang, deadlock, or some other catastrophic failure.

io scheduler noop registered
io scheduler anticipatory registered
io scheduler deadline registered
io scheduler cfq registered (default)

The kernel's I/O scheduler initializes.

Serial: Parrot5/5+ UART driver $Revision: 1.19 $
parrot5-uart.0: ttyPA0 at MMIO 0xd0070000 (irq = 5) is a PARROT5
enabled
parrot5-uart.2: ttyPA2 at MMIO 0xd0090000 (irq = 7) is a PARROT5
parrot5-uart.1: ttyPA1 at MMIO 0xd0080000 (irq = 6) is a PARROT5

Some Universal Asynchronous Receiver/Transmitter (uart) devices, a.k.a. serial ports, are detected. These messages show their memory mapped I/O (MMIO) addresses and their interrupt request (irq) numbers.

DCC: JTAG1 Serial emulation driver driver $Revision: 1.9 $
ttyJ0 at MMIO 0x12345678 (irq = 28) is a DCC

I'm guessing this is some kind of hardware debug port. The Joint Test Action Group (JTAG) defines a standard interface used for hardware and low level software debugging.

using cmd : ec
ONFI param page 0 valid
NAND device: Manufacturer ID: 0x2c, Chip ID: 0xf1 (Micron MT29F1G08AAC)
onfi ecc bits : 1
setting onfi mode 4
status : 00000003
start : 00000000
tim0 : 88111322
tim1 : 00000050
cfg : 18000000
ecc : a4000802
ctrl0 : 10000000
ctrl1 : 00010000
addrlo : ffffff00
addrhi : 00000000
irq status : 00000003
Bad block table found at page 65472, version 0x01
Bad block table found at page 65408, version 0x01
nand_read_bbt: Bad block at 0x01be0000
nand_read_bbt: Bad block at 0x022e0000
nand_read_bbt: Bad block at 0x02800000
nand_read_bbt: Bad block at 0x04ca0000
nand_read_bbt: Bad block at 0x05b80000
5 parrotpart partitions found on MTD device nand0
Creating 5 MTD partitions on "nand0":
0x00000000-0x00040000 : "Pbootloader"
0x00040000-0x00840000 : "Pmain_boot"
0x00840000-0x01040000 : "Pfactory"
0x01040000-0x02040000 : "Psystem"
0x02040000-0x08000000 : "Pupdate"

This is the Memory Technology Device (MTD) driver initializing. MTD is the lowest layer of software in Linux that deals with flash devices. File systems for flash devices are typically built on top of this layer. Note that the names and boundaries of the partitions in the flash memory are listed here. We've seen these before.

UBI: attaching mtd2 to ubi0
UBI: physical eraseblock size:   131072 bytes (128 KiB)
UBI: logical eraseblock size:    126976 bytes
UBI: smallest flash I/O unit:    2048
UBI: sub-page size:              512
UBI: VID header offset:          2048 (aligned 2048)
UBI: data offset:                4096
UBI: attached mtd2 to ubi0
UBI: MTD device name:            "Pfactory"
UBI: MTD device size:            8 MiB
UBI: number of good PEBs:        64
UBI: number of bad PEBs:         0
UBI: max. allowed volumes:       128
UBI: wear-leveling threshold:    4096
UBI: number of internal volumes: 1      512
UBI: VID header offset:          2048 (aligned 2048)
UBI: background thread "ubi_bgt0d" started, PID 763
UBI: attached mtd3 to ubi1
UBI: MTD device name:            "Psystem"
UBI: MTD device size:            16 MiB
UBI: number of good PEBs:        127
UBI: number of bad PEBs:         1
UBI: max. allowed volumes:       128
UBI: wear-leveling threshold:    4096
UBI: number of internal volumes: 1
UBI: number of user volumes:     1
UBI: available PEBs:             0
UBI: total number of reserved PEBs: 127
UBI: number of PEBs reserved for bad PEB handling: 2
UBI: max/mean erase counter: 18/11
UBI: image sequence number: 898781514
UBI: attaching mtd4 to ubi2
UBI: physical eraseblock size:   131072 bytes (128 KiB)
UBI: logical eraseblock size:    126976 bytes
UBI: smallest flash I/O unit:    2048
UBI: sub-page size:              512
UBI: VID header offset:          2048 (aligned 2048)
UBI: data offset:                4096
UBI: background thread "ubi_bgt1d" started, PID 766
UBI: attached mtd4 to ubi2
UBI: MTD device name:            "Pupdate"
UBI: MTD device size:            95 MiB
UBI: number of good PEBs:        758
UBI: number of bad PEBs:         8
UBI: max. allowed volumes:       128
UBI: wear-leveling threshold:    4096
UBI: number of internal volumes: 1
UBI: number of user volumes:     2
UBI: available PEBs:             0
UBI: total number of reserved PEBs: 758
UBI: number of PEBs reserved for bad PEB handling: 7
UBI: max/mean erase counter: 5/4
UBI: image sequence number: 1443597783
UBI: background thread "ubi_bgt2d" started, PID 770

Unsorted Block Image (UBI) is a layer of yet another flash-based file system, UBIFS.

Initializing USB Mass Storage driver...
usbcore: registered new interface driver usb-storage
camera 0-0: P6 camif driver attached to camera 0
camera 1-0: P6 camif driver attached to camera 0
camera 1-0: p6 camif driver detached from camera 0
Parrot6 SPI driver $Revision: 1.8 $
p6_spi: clock = 26000000Hz
p6_spi: tsetupcs = 76ns
p6_spi: tholdcs = 76ns

More device driver initialization. Serial Peripheral Bus (SPI) is a serial bus standard that allows integrated circuits to communicate using a simple protocol over just a handful of pins. I've seen it used to communicate with Ethernet interfaces, with telecommunications interfaces, and with programmable read-only memories (PROMs).

HIFInit
input: p6_kbd_input as /class/input/input0
p6_kbd_input p6_kbd_input.0: driver loaded
dmamem dmamem.0: No static mem pool : big memory allocation can fail
Netfilter messages via NETLINK v0.30.
nf_conntrack version 0.5.0 (2048 buckets, 8192 max)
CONFIG_NF_CT_ACCT is deprecated and will be removed soon. Plase use
nf_conntrack.acct=1 kernel paramater, acct=1 nf_conntrack module option or
sysctl net.netfilter.nf_conntrack_acct=1 to enable it.
ip_tables: (C) 2000-2006 Netfilter Core Team

This is the internet firewall (ip_tables) initializing.

ClusterIP Version 0.8 loaded successfully
arp_tables: (C) 2002 David S. Miller
TCP cubic registered
NET: Registered protocol family 17
RPC: Registered udp transport module.
RPC: Registered tcp transport module.

More IP related stuff initializing.

UBIFS: recovery needed
UBIFS: recovery deferred
UBIFS: mounted UBI device 1, volume 0, name "system"
UBIFS: mounted read-only
UBIFS: file system size:   14221312 bytes (13888 KiB, 13 MiB, 112 LEBs)
UBIFS: journal size:       1015809 bytes (992 KiB, 0 MiB, 6 LEBs)
UBIFS: media format:       w4/r0 (latest is w4/r0)
UBIFS: default compressor: none
UBIFS: reserved for root:  671707 bytes (655 KiB)
VFS: Mounted root (ubifs filesystem) readonly.
Freeing init memory: 116K
UBIFS: completing deferred recovery
UBIFS: deferred recovery completed
UBIFS: mounted UBI device 0, volume 0, name "factory"
UBIFS: mounted read-only
UBIFS: file system size:   6221824 bytes (6076 KiB, 5 MiB, 49 LEBs)
UBIFS: journal size:       1015809 bytes (992 KiB, 0 MiB, 6 LEBs)
UBIFS: media format:       w4/r0 (latest is w4/r0)
UBIFS: recovery needed
UBIFS: recovery completed
UBIFS: mounted UBI device 2, volume 1, name "data"
UBIFS: file system size:   76820480 bytes (75020 KiB, 73 MiB, 605 LEBs)
UBIFS: journal size:       3809280 bytes (3720 KiB, 3 MiB, 30 LEBs)
UBIFS: media format:       w4/r0 (latest is w4/r0)
UBIFS: default compressor: none
UBIFS: reserved for root:  3628421 bytes (3543 KiB)

Here's the top layer of the flash-based UBI File System (UBIFS) initializing as part of the Virtual File System (VFS) layer. Looks like there are three file systems: system, factory, and data.

Parrot6 SDHCI driver $Revision: 1.7 $
gpio 37 is not selected.
Please do it in your board code
p6 mux select pin @0xfd000058 : 0x55500010->0x55500410
gpio 36 is not selected.
Please do it in your board code
p6 mux select pin @0xfd000058 : 0x55500410->0x55500510
using DMA
mmc0: queuing CIS tuple 0x01 length 3
mmc0: queuing CIS tuple 0x1a length 5
mmc0: queuing CIS tuple 0x1b length 8
mmc0: queuing CIS tuple 0x14 length 0
mmc0: queuing CIS tuple 0x80 length 1
mmc0: queuing CIS tuple 0x81 length 1
mmc0: queuing CIS tuple 0x82 length 1
mmc0: new SDIO card at address 0001
AR6000 Reg Code = 0x40000060
channel hint set to 2412
AR6000 updating target stats
AR6000 connected event on freq 2412 with bssid 32:04:7e:50:49:ad  listenInterval=0, beaconInterval = 100, beaconIeLen = 0 assocReqLen=0 assocRespLen =0
Network: Adhoc (Creator)

Secure Digital Hardware Controller Interface (SDHCI) and MultiMediaCard (MMC) are interfaces for removable flash-based storage devices like what you have in your digital camera. I'm guessing this might be part of the interface for the USB port on the bottom of the drone used for firmware updates.

start pwm clock

Update: it took me a while to remember where I'd seen Pulse-Width Modulation (PWM), a digital signal encoding technique, used recently: it was used by a chip to control the speed of cooling fans in a computer chassis. I believe each electric motor's duty cycle, and hence the fan's speed, was tied to the width of "on" pulses (essentially, the percentage of time the line was "on" versus "off") on each fan's electrical power line. I'm taking a SWAG that the pwm clock is used to time the width of pulses to control the individual speed of each AR.drone engine. Precision engine speed control is vital since that's the only mechanism the drone has of maneuvering. I could be all wet; the guys at iFixit have a fascinating tear-down of the AR.drone showing individual microcontrollers at each engine nacelle. But the drone could still use a common clock and PWM to control engine speed.

------------
WARNING: at /home/s_piskorsko/.ardrone/linux/ARDrone_Version_20101202/Linux/kernel/linux/drivers/serial/../parrot/serial/parrot5.c:156 parrot5_serial_int+0x2a0/0x41c()
Modules linked in: p6_sdhci
(warn_on_slowpath+0x4c/0x68)
(parrot5_serial_int+0x2a0/0x41c)
r6:c7cf5c00 r5:c0374e3c r4:c0374f7c
(handle_IRQ_event+0x44/0x84)
(handle_level_irq+0xd0/0x154)
Jan  1 00:00:16 myhc0: 00001904 0008d18c 401fb03c bee2ccf8 401fa000 00002000 0008b188 0008d1a0
r7:00000001 r6:00000080 r5:fc000000 r4:ffffffff
---

I think this is a stack trace that is the result of some failure in a device driver. Because the original source code path was stored in the binary executable by the compiler, we have more clues about Mr. Piskorski's (I stand corrected) software than we might otherwise. I've seen this failure in two firmware loads I've run on the AR.drone. It seems to work fine, so I haven't worried about it.

camera 0-0: P6 camif driver attached to camera 0
camera 1-0: P6 camif driver attached to camera 0

And that's it for /var/log/messages.

Just to add to the flood of information an embedded developer needs to look at, some levels of log messages may be emitted only to the console port, messages may be from applications just using printf(), or emitted by software running before the Linux kernel is even executing, like a boot loader. All of the SoCs that I have used provide one or more serial ports among their I/O controllers, and, fortunately for us, the AR.drone uses one of these as a interactive console upon which it runs a shell under the root account. You can access this port from the bottom of the AR.drone under the rubber cover with the USB symbol on it. Some of the exposed pins provide a TTL-level serial port; some of them provide a USB connection that you can use to apply firmware updates to your drone (about which I will write another time).

The TTL-level serial port means I was wrong about my guess that the AR.drone might export its serial console through a USB serial converter (although I'm finding that to be more and more common in embedded systems). It also means if I brick my drone by botching a change in some boot script, I have some chance of fixing it though the serial console.

(There is a disturbing trend to omit the serial console from embedded systems and only provide root access through a network connection. This is a mistake. But that is a rant for another day.)

Here is what I see on the serial console when my AR.drone boots (again, with some editing for readability).

Parrotboot for target MYKONOS, built on Jan  5 2011

We already suspected that the AR.drone had a multi-stage boot loader. Here's Parrotboot.

->  Change VDD2 reset value
nand_flash: By ONFI Manufacturer: MICRON      , Model: MT29F1G08AAC
nand_flash: Support ONFI v1.0
scaning start 40000 end 800000 page shift 11 eb size 131072
vid_hdr_offset 2048, data_offset 4096 leb_size 126976
image_seq is 6643260f
new volume 4
new volume 0
new volume 1
parsed 4096 pages
volume 0 : main_boot ok
Attempt booting on UBI volume with ID 0...

Booting Linux...

I don't see anything that explicitly says this is a second-stage U-Boot boot loader. In any case, it's loading the Linux kernel from a UBI flash volume.

init started: BusyBox v1.14.0 (2011-02-04 10:06:10 CET)

Again, no big surprise: Linux process 1, init, is implemented by BusyBox.

starting pid 807, tty '': '/etc/init.d/rcS'
init started...
BMI Write Memory (address: 0x502070, filename: /lib/firmware/AR6002/eeprom.data)
BMI Write Memory (address: 0x513950, filename: /lib/firmware/AR6002/eeprom.bin)
BMI Execute (address: 0x913950, param: 0x0)
Return Value from target: 0x0
BMI Set App Start (address: 0x913950)
Updating MAC address
BMI Write compressed Memory (address: 0x502070, filename: /lib/firmware/AR6002/athwlan.bin.z77)
BMI Write Memory (address: 0x52d6c8, filename: /lib/firmware/AR6002/data.patch.hw2_0.bin)
BMI Write Memory (address: 0x500418, value: 0x52d6c8)
BMI Bit-Wise (OR) modify Register (address: 0x500410, orig:0xa, new: 0xb,  mask:0x1)
BMI Done
argc = 7
wmiconfig:fixRateMask=8
wmiconfig:fixRateMask=264
wmiconfig:fixRateMask=2312
SSID=ardrone_040582

Now we are seeing messages from the boot scripts we looked at already.

Creating/Joining Network ardrone_040582
Using address 192.168.1.1
Owner's MAC address is:  00:00:00:00:00:00
Clearing pairing rule
Copy version.txt file in ftp directory
Check if update is necessary ...
File /update/ardrone_update.plf doesn't exists... Start Drone software...
init exit
if you want to customize init look at target/generic/target_skeleton/etc files
if crtl+c does not work look at the Linux FAQ section.

Please press Enter to activate this console. posix init start build on : Feb  4 2011 10:11:00
Use ctrl+\ (SIGQUIT) to end the application
[WW] POS (thread no name ((nil))) RR time quantum 0s 100000000ns
[WW] POS (thread no name ((nil))) thread guard size : default 4096
[WW] POS (thread no name ((nil))) thread stack size : default 6144, minimal 8192, (system default 8380416)
[WW] POS (thread no name ((nil))) disable smp
[WW] POS (thread no name ((nil))) stack size 6144 is too small, setting to 8192
thread start
register : /dev/input/event0
we register 1
init button
16.414392  NULL  6  0  version actuelle du PIC 4003a, version du PLF 4003a
16.417255  NULL  6  1076282856  control checksum PIC
Motors flight anim. callback : <0,0>
Owner's MAC address is: 00:00:00:00:00:00
Clearing pairing rule
16.544275  NULL  6  0  change the ultrasound frequency. 25Hz
Motors leds callback : <0,0,0>
16.545610  NULL  6  7562604  SW VERSION : 0008BA48
Starting thread V4Lcamif
Starting thread V4Lcamif
Starting thread Navdata
Starting thread vp_com_server
Starting thread ATcodec_Commands_Server
Starting thread Acquisition
Starting thread log_thread
Starting thread FlashMgr
Starting thread vbat
Starting thread Video
Starting thread Video_Hori
Starting thread Master
Starting thread Leds
Thread AT Commands Server Start

On their web site, Parrot, the manufacturer of the AR.drone, documents the AT Commands used by the user interface to control the drone across a socket over the WiFi network.

Socket opening failed

Socket opening failed
16.553281  Video  6  982  Camera OK => Launch main video
16.555575  Video_Hori  6  983  Camera OK => Launch main video
[WW] POS (thread log_thread (0x182aac)) suspending current thread, possible deadlock
16.566031  FlashMgr  6  980  Mykonos Configuration saved
16.812523  Master  6  984  BLC backup hex available
16.814454  FlashMgr  6  980  Mykonos Trims loaded from /data/fact_trims.bin theta = 0.000000, phi = 0.000000; psi = 0.000000; gaz_feed_forward = 152.120255
16.824684  FlashMgr  6  980  Mykonos Trims loaded from /data/trims.bin theta = 0.000000, phi = 0.000000; psi = 0.000000; gaz_feed_forward = 152.120255
16.833238  FlashMgr  6  980  Mykonos Accs Infos loaded from /data/fact_accs_infos.bin: val(0) = 0.000000; val(1) = 0.000000; val(2) = 0.000000
16.840295  Master  6  984  BLC call for motor 1
16.842558  FlashMgr  6  980  Mykonos Accs Infos loaded from /data/accs_infos.bin: val(0) = -22.247375; val(1) = 106.571831; val(2) = -1000.394531
16.861106  Master  6  984  BLC check BLC memory corruption on motor 1
16.861273  Master  6  984  BLC verify
16.880109  Master  6  984  BLC verify OK

vision camera config truly vga

vision camera config cresyn qcif
17.092351  Master  6  984  BLC motor 1 soft version 1.15, hard version 3.0, supplier 1.1, lot number 06/10, FVT1 01/06/10
17.150069  Master  6  984  BLC call for motor 2
17.170837  Master  6  984  BLC check BLC memory corruption on motor 2
17.170995  Master  6  984  BLC verify
17.189731  Master  6  984  BLC verify OK
17.402346  Master  6  984  BLC motor 2 soft version 1.15, hard version 3.0, supplier 1.1, lot number 06/10, FVT1 01/06/10
17.460038  Master  6  984  BLC call for motor 3
17.480814  Master  6  984  BLC check BLC memory corruption on motor 3
17.480972  Master  6  984  BLC verify
17.499694  Master  6  984  BLC verify OK
17.712339  Master  6  984  BLC motor 3 soft version 1.15, hard version 3.0, supplier 1.1, lot number 06/10, FVT1 01/06/10
17.770052  Master  6  984  BLC call for motor 4
17.790688  Master  6  984  BLC check BLC memory corruption on motor 4
17.790829  Master  6  984  BLC verify
17.809447  Master  6  984  BLC verify OK
18.022346  Master  6  984  BLC motor 4 soft version 1.15, hard version 3.0, supplier 1.1, lot number 06/10, FVT1 01/06/10
18.080297  Acquisition  6  978  HARD VERSION c0
18.080467  Acquisition  6  978  change the ultrasound frequency. 25Hz



<starting info>Version="AR.Drone 1.5.1" WIFI="OK" AddrMAC="00:26:7E:50:5D:A6" Calibration="OK" PICVersion="4.58" Motor1Version="1.15" Motor2Version="1.15" Motor3Version="1.15" Motor4Version="1.15"</starting info>

This looks like XML. This amuses me greatly for some reason.

18.082599  Master  6  984   *********   Previous runs gave emergency   *********
18.082741  Master  6  984   Angles out of range !!!
18.082829  Master  6  984  mykonos_state = 0xcf880800
18.082887  Master  6  984  vbat = 12534
18.083023  Master  6  984  ctrl_state = 0x00000000
18.083106  Master  6  984   -----------------------------------
18.083168  Master  6  984   Angles out of range !!!
18.083224  Master  6  984  mykonos_state = 0xcf880800
18.083277  Master  6  984  vbat = 12244
18.083329  Master  6  984  ctrl_state = 0x00000000
18.083381  Master  6  984   -----------------------------------
18.083435  Master  6  984   Emergency signal sent by user !!!
18.083490  Master  6  984  mykonos_state = 0x8f8b0000
18.083543  Master  6  984  vbat = 12230
18.083593  Master  6  984  ctrl_state = 0x00000000
18.083645  Master  6  984   -----------------------------------
18.083698  Master  6  984   Angles out of range !!!
18.083751  Master  6  984  mykonos_state = 0x8f880014
18.083802  Master  6  984  vbat = 11592
18.083852  Master  6  984  ctrl_state = 0x00000000
18.083903  Master  6  984   -----------------------------------
18.083955  Master  6  984   Angles out of range !!!
18.084007  Master  6  984  mykonos_state = 0xcf880c10
18.084075  Master  6  984  vbat = 12600
18.084126  Master  6  984  ctrl_state = 0x00000000
18.084179  Master  6  984   -----------------------------------
18.084231  Master  6  984  Wifi disconnection !!!
18.084283  Master  6  984  mykonos_state = 0xcfca2c10
18.084351  Master  6  984  vbat = 12600
18.084405  Master  6  984  ctrl_state = 0x00000000
18.084458  Master  6  984   -----------------------------------
18.084510  Master  6  984   Emergency signal sent by user !!!
18.084563  Master  6  984  mykonos_state = 0x8fe30404
18.084613  Master  6  984  vbat = 12250
18.084663  Master  6  984  ctrl_state = 0x00000000
18.084715  Master  6  984   -----------------------------------
18.084768  Master  6  984   Emergency signal sent by user !!!
18.084820  Master  6  984  mykonos_state = 0x8f810435
18.084870  Master  6  984  vbat = 12211
18.084927  Master  6  984  ctrl_state = 0x00000000
18.084985  Master  6  984   -----------------------------------
18.085039  Master  6  984  Wifi disconnection !!!
18.085091  Master  6  984  mykonos_state = 0xcf802c10
18.085141  Master  6  984  vbat = 12035
18.085204  Master  6  984  ctrl_state = 0x00000002
18.085259  Master  6  984   -----------------------------------
18.085311  Master  6  984   Emergency signal sent by user !!!
18.085365  Master  6  984  mykonos_state = 0x8fc30414
18.085414  Master  6  984  vbat = 11922
18.085463  Master  6  984  ctrl_state = 0x00000000
18.085516  Master  6  984   -----------------------------------
18.085567  Master  6  984  Wifi disconnection !!!
18.085618  Master  6  984  mykonos_state = 0xcf802c14
18.085669  Master  6  984  vbat = 11734
18.085718  Master  6  984  ctrl_state = 0x00000002
18.085769  Master  6  984   -----------------------------------
18.085830  Master  6  984  Wifi disconnection !!!
18.085884  Master  6  984  mykonos_state = 0xcf802c10
18.085936  Master  6  984  vbat = 11594
18.085987  Master  6  984  ctrl_state = 0x00000002
18.086053  Master  6  984   -----------------------------------
18.086104  Master  6  984  Wifi disconnection !!!
18.086155  Master  6  984  mykonos_state = 0xcf802c10
18.086205  Master  6  984  vbat = 11510
18.086255  Master  6  984  ctrl_state = 0x00000002
18.086306  Master  6  984   -----------------------------------
18.086358  Master  6  984  Wifi disconnection !!!
18.086410  Master  6  984  mykonos_state = 0xcf802414
18.086462  Master  6  984  vbat = 11312
18.086513  Master  6  984  ctrl_state = 0x00000002
18.086566  Master  6  984   -----------------------------------
18.420666  Master  6  984  Wifi disconnection !!!
18.420781  Master  6  984  mykonos_state = 0xcf802c10
18.420842  Master  6  984  vbat = 12600
18.420897  Master  6  984  ctrl_state = 0x00000002
18.420957  Master  6  984   -----------------------------------
18.421014  Master  6  984  Wifi disconnection !!!
18.421415  Master  6  984  mykonos_state = 0xcf802c10
18.421495  Master  6  984  vbat = 12054
18.421554  Master  6  984  ctrl_state = 0x00000002
18.421613  Master  6  984   -----------------------------------
18.421667  Master  6  984  Wifi disconnection !!!
18.421720  Master  6  984  mykonos_state = 0xcf802c10
18.421769  Master  6  984  vbat = 11654
18.421817  Master  6  984  ctrl_state = 0x00000002
18.421870  Master  6  984   -----------------------------------
18.421920  Master  6  984   Emergency signal sent by user !!!
18.421972  Master  6  984  mykonos_state = 0x8f810415
18.422023  Master  6  984  vbat = 11001
18.422071  Master  6  984  ctrl_state = 0x00000000
18.422122  Master  6  984   -----------------------------------
18.422171  Master  6  984   Vbat low !!!
18.422220  Master  6  984  mykonos_state = 0x8f808414
18.422269  Master  6  984  vbat = 9829
18.422318  Master  6  984  ctrl_state = 0x00000002
18.422370  Master  6  984   -----------------------------------
18.422421  Master  6  984  Wifi disconnection !!!
18.422494  Master  6  984  mykonos_state = 0xcf802c10
18.422550  Master  6  984  vbat = 12015
18.422602  Master  6  984  ctrl_state = 0x00000002
18.422657  Master  6  984   -----------------------------------
18.422708  Master  6  984   Emergency signal sent by user !!!
18.422761  Master  6  984  mykonos_state = 0x8f810455
18.422810  Master  6  984  vbat = 11139
18.422861  Master  6  984  ctrl_state = 0x00000000
18.422911  Master  6  984   -----------------------------------
18.422961  Master  6  984  Wifi disconnection !!!
18.423027  Master  6  984  mykonos_state = 0xcf802c10
18.423081  Master  6  984  vbat = 12600
18.423132  Master  6  984  ctrl_state = 0x00000002
18.423184  Master  6  984   -----------------------------------
18.423235  Master  6  984   Angles out of range !!!
18.423287  Master  6  984  mykonos_state = 0xcf880c10
18.423336  Master  6  984  vbat = 12600
18.423386  Master  6  984  ctrl_state = 0x00000000
18.423437  Master  6  984   -----------------------------------
18.423489  Master  6  984  Wifi disconnection !!!
18.423538  Master  6  984  mykonos_state = 0xcf802c10
18.423587  Master  6  984  vbat = 12600
18.423635  Master  6  984  ctrl_state = 0x00000002
18.423686  Master  6  984   -----------------------------------
18.423736  Master  6  984  Wifi disconnection !!!
18.423786  Master  6  984  mykonos_state = 0xcf802c10
18.423836  Master  6  984  vbat = 12600
18.423885  Master  6  984  ctrl_state = 0x00000002
18.423935  Master  6  984   -----------------------------------
18.423984  Master  6  984   Emergency signal sent by user !!!
18.424035  Master  6  984  mykonos_state = 0x8fc30414
18.424083  Master  6  984  vbat = 11615
18.424132  Master  6  984  ctrl_state = 0x00000000
18.424200  Master  6  984   -----------------------------------
18.424254  Master  6  984   Emergency signal sent by user !!!
18.424308  Master  6  984  mykonos_state = 0x8fc30414
18.424359  Master  6  984  vbat = 12430
18.424410  Master  6  984  ctrl_state = 0x00000000
18.424462  Master  6  984   -----------------------------------
18.424513  Master  6  984   Emergency signal sent by user !!!
18.424564  Master  6  984  mykonos_state = 0x8fc30414
18.424612  Master  6  984  vbat = 12018
18.424659  Master  6  984  ctrl_state = 0x00000000
18.424710  Master  6  984   -----------------------------------
18.424760  Master  6  984   Angles out of range !!!
18.424811  Master  6  984  mykonos_state = 0x8f880414
18.424861  Master  6  984  vbat = 11765

My drone is really unhappy about sitting side-goggling on my desk!

18.720780  Acquisition  6  978  GAINS AT : pq_kp = 20000, r_kp = 100000, r_ki = 10000, ea_kp = 9000, ea_ki = 8000, alt_kp = 2000, alt_ki = 400, vz_kp = 100,                               vz_ki = 50, hov_kp = 80
18.971519  Acquisition  6  978  GAINS AT : pq_kp = 20000, r_kp = 100000, r_ki = 10000, ea_kp = 9000, ea_ki = 8000, alt_kp = 2000, alt_ki = 400, vz_kp = 100,                               vz_ki = 50, hov_kp = 8000, hov_ki =8000
camera configured

vision camera config cresyn qcif

vision camera config cresyn qcif

vision camera config cresyn qcif
dct status 0x0


starting pid 959, tty '/dev/ttyPA0': '/bin/sh'

We already knew from our prior poking around that /dev/ttyPA0 is the serial console.

BusyBox v1.14.0 (2011-02-04 10:06:10 CET) built-in shell (ash)
Enter 'help' for a list of built-in commands.

#

And now we have a root shell prompt provided by a shell implemented in, what else, BusyBox.

Next up: we take a break from software and look at some of the tools I've used to get this far.