A small freedom area.

Story of debugging a crash in MPD

Wed 12 Aug 2020

prog, debug, reverse, av

Getting close to 3 years without posting. I haven't been peacefully enjoying a retired commoner life during all this time. If anything, I'm angrier and overdoing things more than ever. At the same time, the queue of blog posts to write and publish keeps growing as well, so it's time to give it a stab.

Today, I'm going to talk about a random bug that occurred while playing with my web audio stream. Long story short, I have a local MPD pushing to a remote Icecast using the "shout" audio output. I'm usually relying on that setup to listen to my music when I'm not at home. But this time, MPD kept crashing.

I naively asked on IRC if such an obvious bug was already known, and the answer was "no crash bugs are currently known. report them with full backtraces".

Spoiler alert: the bug is not in MPD.

Starting point

# coredumpctl info
           PID: 415 (mpd)
           UID: 45 (mpd)
           GID: 45 (mpd)
        Signal: 11 (SEGV)
     Timestamp: Sun 2020-08-02 12:24:58 CEST (4h 16min ago)
  Command Line: /usr/bin/mpd --no-daemon
    Executable: /usr/bin/mpd
 Control Group: /user.slice/user-45.slice/user@45.service/mpd.service
          Unit: user@45.service
     User Unit: mpd.service
         Slice: user-45.slice
     Owner UID: 45 (mpd)
       Boot ID: 6f57bce0857b45509356e5e01298eea0
    Machine ID: 799f672765424647aa2b2bbaea25145c
      Hostname: kaeru
       Storage: /var/lib/systemd/coredump/core.mpd.45.6f57bce0857b45509356e5e01298eea0.415.1596363898000000000000.lz4
       Message: Process 415 (mpd) of user 45 dumped core.

                Stack trace of thread 462:
                #0  0x0000ffff9269f444 memcpy (libc.so.6 + 0x81444)
                #1  0x0000ffff939c47c4 n/a (libshout.so.3 + 0xd7c4)
                #2  0x0000aaaaea7b6778 n/a (mpd + 0xd4778)
                #3  0x0000aaaaea7b6de0 n/a (mpd + 0xd4de0)
                #4  0x0000aaaaea7a0a64 n/a (mpd + 0xbea64)
                #5  0x0000aaaaea7a1d80 n/a (mpd + 0xbfd80)
                #6  0x0000aaaaea7a2ab4 n/a (mpd + 0xc0ab4)
                #7  0x0000aaaaea763270 n/a (mpd + 0x81270)
                #8  0x0000ffff939ee4b8 start_thread (libpthread.so.0 + 0x84b8)
                #9  0x0000ffff926ee95c thread_start (libc.so.6 + 0xd095c)

       [<snip thread-lock backtraces>]

For the context, this is a low cost ARM (aarch64) board running Arch Linux ARM. I'm basically able to reproduce the issue by randomly toggling on and off both the shout output and the music playback.

This is the kind of situation where debugging is painful for several reasons:

Identifying the crash source

The method I used to identify the code responsible for the crash just required to install GDB on the board, run coredumpctl gdb, and x/10x 0x0000aaaaea7b6778 (this is frame #2, the last frame in MPD before entering libshout.so). The reason I'm looking here is because MPD is the top brick and it might be misusing its libraries.

After grabbing the /usr/bin/mpd binary locally from the board, and loading it in Ghidra, I byte-search the 10 bytes dump by the x/10x command, which brings me here (on the blr instruction):

centerimg

Alright well, easy enough then, it's the part of the code in MPD that calls shout_send(). We're fortunate, there is only one call in MPD, in src/output/plugins/ShoutOutputPlugin.cxx:

static void
EncoderToShout(shout_t *shout_conn, Encoder &encoder,
           unsigned char *buffer, size_t buffer_size)
{
    while (true) {
        size_t nbytes = encoder.Read(buffer, buffer_size);
        if (nbytes == 0)
            return;

        int err = shout_send(shout_conn, buffer, nbytes);
        HandleShoutError(shout_conn, err);
    }
}

I want to observe the value of the 3 parameters shout_conn, buffer and nbytes by looking at the first 3 registers at frame #2:

(gdb) bt
#0  0x0000ffff9269f444 in memcpy () at /usr/lib/libc.so.6
#1  0x0000ffff939c47c4 in  () at /usr/lib/libshout.so.3
#2  0x0000aaaaea7b6778 in  ()
#3  0x0000aaaaea7b6de0 in  ()
#4  0x0000aaaaea7a0a64 in  ()
#5  0x0000aaaaea7a1d80 in  ()
#6  0x0000aaaaea7a2ab4 in  ()
#7  0x0000aaaaea763270 in  ()
#8  0x0000ffff939ee4b8 in start_thread () at /usr/lib/libpthread.so.0
#9  0x0000ffff926ee95c in thread_start () at /usr/lib/libc.so.6
(gdb) frame 2
#2  0x0000aaaaea7b6778 in ?? ()
(gdb) i r
x0             0xaaaa8e85e4c2      187649512301762
x1             0xaaaaf6e9d46c      187651263681644
x2             0x3a                58
[...]

Unfortunately, these 3 parameters do not correspond to the registers at frame #2, they correspond to the values at frame #0 (memcpy arguments, potentially modified within the function). Some registers seem to change between frames, but not those, which means that GDB is pretty much useless here. According to the doc, this is what info registers does:

Print the names and values of all registers except floating-point and vector registers (in the selected stack frame).

Source: Debugging with GDB: Registers

But of course it can't because these registers weren't saved anywhere: they are call clobbered. Functions can modify them and do not need to restore them, so they don't end up saved on the stack, and as a result GDB can't reconstruct them. It would have been much better if GDB was printing <unknown> or tagging with <unreliable> such registers when we are on a frame ≠ #0.

Anyway, let's see what we get in libshout.so (down one level, at frame #1) instead. Using the same method used with MPD, we easily identify this code in icecast-libshout (src/format_ogg.c):

static int send_ogg(shout_t *self, const unsigned char *data, size_t len)
{
    ogg_data_t  *ogg_data = (ogg_data_t*)self->format_data;
    ogg_codec_t *codec;
    char        *buffer;
    ogg_page     page;

    buffer = ogg_sync_buffer(&ogg_data->oy, len);
    memcpy(buffer, data, len);
    ogg_sync_wrote(&ogg_data->oy, len);

We know the crash happens inside that memcpy call. First thing we observe here is that ogg_sync_buffer() is unchecked and can actually return NULL in several scenarios, this one for a start:

char *ogg_sync_buffer(ogg_sync_state *oy, long size){
  if(ogg_sync_check(oy)) return NULL;
  // ...

The SIGSEGV does indeed happens on a write instruction (stp) meaning that we have an invalid destination buffer. Well then, we already have a patch to try out:

diff --git a/src/format_ogg.c b/src/format_ogg.c
index 9d852c4..b694911 100644
--- a/src/format_ogg.c
+++ b/src/format_ogg.c
@@ -92,6 +92,8 @@ static int send_ogg(shout_t *self, const unsigned char *data, size_t len)
     ogg_page     page;

     buffer = ogg_sync_buffer(&ogg_data->oy, len);
+    if (!buffer)
+        return self->error = SHOUTERR_INSANE;
     memcpy(buffer, data, len);
     ogg_sync_wrote(&ogg_data->oy, len);

But in our case, the pointer looks far from being NULL if we look at the registers, so it's likely another scenario. The rest of the function looks rather correct, so we'll keep that patch in standby while we're getting deeper.

Down the rabbit hole

Down into libogg this time. Just in case ogg_sync_buffer() is returning an invalid buffer, we can have a look at what's going on there.

First, here is a small aggregation of a few useful definitions to understand the context:

typedef struct {
  unsigned char *data;
  int storage;
  int fill;
  int returned;

  int unsynced;
  int headerbytes;
  int bodybytes;
} ogg_sync_state;

/* ... */

typedef struct {
    ogg_sync_state  oy;
    ogg_codec_t    *codecs;
    char            bos;
} ogg_data_t;

We have a ring buffer with data the base pointer, storage the total number allocated, fill how much is filled, and returned corresponding to what has been consumed.

Only scenario where I see the ogg_sync_buffer() fail would be if the values are inconsistent, typically with returned being larger than fill.

After staring at the code for a while, I couldn't notice anything special. Remember, I don't have much tools to actually debug or make any modification yet, so building up a mental model without any data is getting trickier as I'm getting deeper.

Still, one thing is suspicious: the growing buffer size (newsize) is held in a long but saved in an int (storage):

char *ogg_sync_buffer(ogg_sync_state *oy, long size){
  if(ogg_sync_check(oy)) return NULL;

  /* first, clear out any space that has been previously returned */
  if(oy->returned){
    oy->fill-=oy->returned;
    if(oy->fill>0)
      memmove(oy->data,oy->data+oy->returned,oy->fill);
    oy->returned=0;
  }

  if(size>oy->storage-oy->fill){
    /* We need to extend the internal buffer */
    long newsize=size+oy->fill+4096; /* an extra page to be nice */
    void *ret;

    if(oy->data)
      ret=_ogg_realloc(oy->data,newsize);
    else
      ret=_ogg_malloc(newsize);
    if(!ret){
      ogg_sync_clear(oy);
      return NULL;
    }
    oy->data=ret;
    oy->storage=newsize;
  }

  /* expose a segment at least as large as requested at the fill mark */
  return((char *)oy->data+oy->fill);
}

I have doubts this is the issue I'm getting, but it's still something we have to address. We'll make another patch for that.

At this point, I've been playing with a lot of assumptions, but one thing I'm reassured of is that it doesn't look like an architecture specific issue (with multimedia stuff, you really never know), so I'm more confident that I'll be able to reproduce it locally. Since I can't go much further without actual debugging, I'm adjusting the strategy.

Switching to easy mode

I now have some more time to construct a similar but simplified setup locally.

MPD setup

We first need a minimal MPD with a shout output, let's go with the following ~/mpd.conf:

log_file    "/home/ux/mpd.log"
db_file     "/home/ux/mpd.db"
music_directory "/home/ux/x"

audio_output {
    type        "shout"
    name        "My Shout Stream"
    host        "localhost"
    port        "8000"
    mount       "/mpd.ogg"
    password    "hackme"
    bitrate     "128"
    format      "44100:16:1"
}

We add a random music file in ~/x and can start it in standalone with mpd --no-daemon --stderr mpd.conf.

Icecast setup

I don't need to make a custom build or actually debug Icecast, so we can install it on the system and be done with it. But of course the package is broken out of the box, so we need to find a workaround for a stupid permission issue. I don't do that often but I have to commend the quick reaction and fix here. Quickly enough, systemctl start icecast is working again.

Crashing it

Since using ncmpcpp or another UI for controlling MPD is burdensome for automation, we need to identify a minimal number of steps to reproduce the issue. So here it is, with mpc:

mpc add /
mpc play
mpc toggleoutput 1
mpc toggleoutput 1
mpc play

We can save that in a shell script and happily trigger the crash as much as we want.

Tooling

Last step: valgrind, the joker tool for almost every possible memory issue. I wanted to do something smart with the vgdb attach system, but a bug in the packaging prevented me from reading the manual so I had to let it go. Maybe one day someone will explain to me why everything I try is always broken one way or another.

A first run with helgrind (thread sanitizer) revealed a race in MPD, but apparently only in a debugging scenario according to someone on IRC, so I ignored that one...

With the default Valgrind mode though, we quickly realize that the invalid write to the buffer is a use after free issue.

End of the road

The rest of the story is pretty uninteresting (valgrind did all the job really) so I'll skip down to the answer: libshout has a shout_t context which the user configures. Then you can call shout_open() and shout_close() on it. Problem is that doing that several times on the same context causes a re-use of previous data (allocated by the open) because it isn't cleaned up properly (in the close). This happens typically when you turn on and off the audio stream (the mpc toggleoutput commands do that, or in my case in the view 7 of ncmpcpp). Pretty boring and uninteresting bug overall, but the path was interesting given that my main goal was initially to see how far I could go without actually being on a workstation.

The patch itself is simple enough, and it actually baffles me that no one addressed it before that. Looking at the libshout tracker, I found the bug was actually reported a year ago.

In the end, I made the 3 patches and they were upstreamed:

  1. ogg: framing: check for overflow on growing buffer (684c7377)
  2. libshout: Fix: cleanup format residual after close (6598fd21)
  3. libshout: Fix: check ogg_sync_buffer() pointer before writing to it (9d3bed1a)

2nd commit in that list being the important fix.

Everything is broken

Frankly, I don't understand how software can be so broken, even at such low levels like this, where things don't even change much lately. This blog post is about 3 bugs including a critical one, but along the way so much shit happened such as the 2 packaging specific issues (Icecast, Valgrind). But GDB is also unreliable, and I'm not even talking about the i915 GPU hangs I had every 15 minutes or so (for totally unrelated reasons). And after all of this is fixed and I think I can listen to my stream, I realize there is now a bug in the ogg demuxer of my player, causing a huge CPU and memory consumption after a few minutes of listening to the stream. I haven't made an exhaustive list, but during my 2 days of investigation, I got hit by more bugs than my hands can count.

The amount of effort I have to make just to be able to listen to my music is not humanly acceptable, and it's no surprise so many people eat proprietary garbage software on a daily basis. And yes I know, it's my fault for using a bleeding edge distribution, and C code is full of memory issues, Rust is the best, blablabla. I still believe we could do much better in the current state. Testing software and being held to higher standards don't need to be reserved to modern languages and stable distributions. The core issue is how we break this mentality of "bugs don't matter because we can just fix them quickly".

To be honest, I've lost all hopes for things to ever get better in any way in this world, but I still won't surrender to making things even worse. See you soon for another blog post.

index