Corrupt data stream

[MorningLightMountain713]

Hi there, really like emlog, thank you all.

Was hoping you could point me in the right direction for some debug issues I’m having with emlog.

I’m writing data to an emlog device and reading from it.

Everything seems to work fine until the buffer fills up. (It is very dependent on the write rate I believe) if the write rate is slow the buffer wraps and I don’t have a problem.

My c program uses blocking reads, it sits there waiting for my other program to write. What I think is happening is that the head of the file is moving back over data I’ve already read. This is variable, sometimes I’ve noticed 512 bytes, sometimes 1322. I’m assuming it’s the size of the write that has just occurred.

Basically, means the next read I do is garbage. (Well, data I’ve already read) and my data stream is now corrupt.

This must be some sort of timing issue as when I go and hex dump the emlog device - the data is in the correct sequence again.

Do you have any idea how I could find out what is going on? Eg get the location of the head / tail of the buffer? Or how can I call get_einfo to get the data?

[ahippo]

Huh, that's weird.
Do you have a simple reproducer code by any chance?

Well, I'd suggest adding more pr_debug()'s into the module itself.
For example, you can dump the whole struct emlog_info contents on every read and write to see if there is anything suspicious.

[MorningLightMountain713]

I figured it out.

Race condition between writer and reader. On an embedded system with no preemption this wouldn't be a problem. However on any SMP system it is.

if (*offset < einfo->offset)
      *offset = einfo->offset;

  /* is the user trying to read past EOF? */
  if (*offset >= EMLOG_FIRST_EMPTY_BYTE(einfo))
      return NULL;

  /* find the smaller of the total bytes we have available and what
   * the user is asking for */
  *length = min_t(size_t, *length, EMLOG_FIRST_EMPTY_BYTE(einfo) - *offset);
  remaining = *length;

  /* figure out where to start based on user's offset */
  start_point = einfo->read_point + (*offset - einfo->offset);

If a writer comes in and writes something inbetween the reader reading einfo->offset for the first time and the second time - you end up with the start point being smaller than it should be by the last write.

I guess this isn't a problem on a simple logger - I'm using it for something else though and it is a problem.

I fixed the issue by using a read_lock and a write_lock around the critical sections. Not sure if this is the best approach though, I will most likely be starving readers under high load.

[ahippo]

Race condition between writer and reader. On an embedded system with no preemption this wouldn't be a problem. However on any SMP system it is.

Great finding!
Yeah, I think, you're right.
Also, einfo->read_point may be adjusted by write after the read side has calculated start_point.

I guess this isn't a problem on a simple logger - I'm using it for something else though and it is a problem.

Well, it's still a correctness issue, and it may produce quite confusing logs.

As far as I can see, there are a few other races (which don't need to be addressed here):

• with emlog_info_list manipulation (create_einfo() vs free_einfo())
• with new einfo allocation (get_einfo() vs create_einfo())

I fixed the issue by using a read_lock and a write_lock around the critical sections. Not sure if this is the best approach though, I will most likely be starving readers under high load.

I'll be glad to merge your fix as is -- it's better than silently producing corrupt data.
On non-SMP non-preempt kernel they wouldn't add much overhead, and solve the correctness issue on SMP/preemt.
Are the locks per-einfo?

[ahippo]

I'll be glad to merge your fix as is -- it's better than silently producing corrupt data.

And we can explore (later) if we can use generic circular buffer implementation (<linux/circ_buf.h> or even <linux/ring_buffer.h>) with independent reader-only and writer-only locks.