kernel/printk/printk.c: Invalid access when buffer wraps around?

[Vincent Brillault]

Dear all,

First of all, I'm sorry to send you this direct email, but it seems that
there is no entry for kernel/printk/printk.c in MAINTAINERS, so I can
only notify you, who have touched this part of the code...

While working on a kernel module that basically forks
kernel/printk/printk.c to create its own buffer, I believe I have found
a bug in how printk wraps around its buffer: In a very specific case, a
reader, trying to read what was supposed to be a zeroed header
indicating that the buffer wrapped, might read random data from another
message that has overridden it. The root of the problems seems to be
that the zeroed header placed at the end of the buffer is not protected
by the sequence number checks.

I've attached two files to this email:
- An explanation of the bug, including key parts of the code.
- A simplified example on how the bug can be triggered.

I believe that this bug is very difficult to trigger and, as a user
don't have proper control on the content of the printk buffer, it can at
most lead to a kernel panic in some very unfortunate circumstances.

Sincerely yours,
Vincent Brillault
Description of the printk buffer from the headers:
```
The printk log buffer consists of a chain of concatenated variable
length records. Every record starts with a record header, containing
the overall length of the record.

The heads to the first and last entry in the buffer, as well as the
sequence numbers of these entries are maintained when messages are
stored.

If the heads indicate available messages, the length in the header
tells the start next message. A length == 0 for the next message
indicates a wrap-around to the beginning of the buffer.
```


To be precies, these `heads' are:
```
/* index and sequence number of the first record stored in the buffer */
static u64 log_first_seq;
static u32 log_first_idx;

/* index and sequence number of the next record to store in the buffer */
static u64 log_next_seq;
static u32 log_next_idx;
```

The `seq`, or sequence number, is an unsigned number on 64bits, stricly
increasing. Wrapping is not supported, but given the size of that number
and the frequency of kernel messages, wrapping should never happen.

The `idx`, or index, is the offset in bytes of the message in the buffer.

These `heads` are maintained by the writer (`log_store`) which basically,
when it has enough space simply:
- Write a header and data at log_next_idx 
- Increase the sequence number and the index:
   ```
        /* insert message */
        log_next_idx += msg->len;
        log_next_seq++;
   ```


The readers will maintain similar index and sequence numbers, for example:
```
struct devkmsg_user {
        u64 seq;
        u32 idx;
        enum log_flags prev;
        struct mutex lock;
        char buf[CONSOLE_EXT_LOG_MAX];
};
```
At any given, these index and sequence numbers point to the next message
that the reader will read (when given the opportunity to).


As this is a circular buffer, messages need to be deleted, by updating
the first entry in the buffer. This is done by this code:
```
static int log_make_free_space(u32 msg_size)
{
        while (log_first_seq < log_next_seq &&
               !logbuf_has_space(msg_size, false)) {
                /* drop old messages until we have enough contiguous space */
                log_first_idx = log_next(log_first_idx);
                log_first_seq++;
        }

        if (clear_seq < log_first_seq) {
                clear_seq = log_first_seq;
                clear_idx = log_first_idx;
        }

        /* sequence numbers are equal, so the log buffer is empty */
        if (logbuf_has_space(msg_size, log_first_seq == log_next_seq))
                return 0;

        return -ENOMEM;
}
```


In reaction, the reader has to verify if the entry he wants to read
is still valid or if it has been invalidated (i.e) removed in the mean time.
This code is responsible for this check:
```
        while (user->seq == log_next_seq) {
                if (file->f_flags & O_NONBLOCK) {
                        ret = -EAGAIN;
                        raw_spin_unlock_irq(&logbuf_lock);
                        goto out;
                }

                raw_spin_unlock_irq(&logbuf_lock);
                ret = wait_event_interruptible(log_wait,
                                               user->seq != log_next_seq);
                if (ret)
                        goto out;
                raw_spin_lock_irq(&logbuf_lock);
        }

        if (user->seq < log_first_seq) {
                /* our last seen message is gone, return error and reset */
                user->idx = log_first_idx;
                user->seq = log_first_seq;
                ret = -EPIPE;
                raw_spin_unlock_irq(&logbuf_lock);
                goto out;
        }
```


Just after this check, the reader will read the memory pointed by user->idx
with `msg = log_from_idx(user->idx);`, which simply means:
```
/* get record by index; idx must point to valid msg */
static struct printk_log *log_from_idx(u32 idx)
{
        struct printk_log *msg = (struct printk_log *)(log_buf + idx);

        /*
         * A length == 0 record is the end of buffer marker. Wrap around and
         * read the message at the start of the buffer.
         */
        if (!msg->len)
                return (struct printk_log *)log_buf;
        return msg;
}
```


Let's now concentrate on buffer wrapping. The writer, if there is no memory
avaliable will free memory (see `log_make_free_space`, previously quoted).
When freeing that memory, it may wrap and thus has to start putting messages
again at the beginning of the buffer. Here is the code responsible:
```
        if (log_next_idx + size + sizeof(struct printk_log) > log_buf_len) {
                /*
                 * This message + an additional empty header does not fit
                 * at the end of the buffer. Add an empty header with len == 0
                 * to signify a wrap around.
                 */
                memset(log_buf + log_next_idx, 0, sizeof(struct printk_log));
                log_next_idx = 0;
        }
```

As you can see, the writer simply writes zeros at the current position and
move the index to the beginning. The reader uses the same convention, and
if it reads a zeroed header (in fact only the len matters), it will move its
index to the beginning (see `log_from_idx`).

However, this index change is done without any sequence change and thus
that very zeroed memory is not protected by the sequence check! In some very
specific circonstances, the reader might try to access a zeroed header which
has already been overriden.


To be specific, these circonstances are:
- The buffer is almost full and the `log_next_seq` is closed to the end,
  but there is still place for small messages
- A reader updates its index and sequence to log_next_*
- The next message is too large, resulting in the buffer wrapping-around and
   a zeroed header to be added at the reader index position
- The buffer is completely filled with new messages but without wrapping:
 + The last message must not wrap around (thus log_first_seq will be equal to
    the readers's index)
 + The last message must override the zeroed header (Trigerring the bug)
- The reader starts reading again, finding random data instead of the zero
  'len' it was supposed to read...
Here is an example, considering a smaller (empty) 70 char buffer:
......................................................................

For simplicity, we'll note messages as their sequence number (artificially
starting at one), empty area as dots and zeroed area as zero and consider
that the header is only one char. This does not change anything in the logic
but simplifies the schema.

Let's start by filling the buffers with some messages:
1111112222222222222333333344444444455555555555666666667777............

At that moment, we have:
log_first_seq = 1, log_next_seq = 8
log_first_idx = 0, log_next_idx = 58

Let's now starts a reader, which will read everything and wait with:
seq = 8, idx = 58

Due to scheduling/reader choice, the reader now stops.
A 20 character-long message arrives. The buffers removes messages from before
and wraps arround:
88888888888888888883333333444444444555555555556666666677770...........

And we now have:
log_first_seq = 3, log_next_seq = 9
log_first_idx = 20, log_next_idx = 20

Let's continue filling the buffer, without wrapping:
88888888888888888889999999999999999999aaaaaaaaaaaaabbbbbbbbbbbbbb.....

We now have:
log_first_seq = 8, log_next_seq = 0xc
log_first_idx = 0, log_next_idx = 65

And now the reader restarts, it still have the same sequence number, '8'
As `seq < log_first_seq` is false, it will consider that this message is valid
and continue. Unfortunately, it's first action will be `log_from_idx(idx)`,
which will first try to read the header of the message at the offset `idx`.
This header, which was supposed to be zeroed due to the wrap-around, has now
been overritten and thus contain random junk, which might ultimately lead
to a kernel panic (wrong memory access from the reader).

As I understand it, the underlying problem is that the zeroed-header is
not properly protected by the sequence number cheks.

Attachment: signature.asc
Description: OpenPGP digital signature