repeatable w1_therm module crash

[Otherbright]

This bug is repeatable if you are waiting/reading the device temperature (for example /sys/bus/w1/devices/28-000006157bcd/w1_slave) while the device is deleted from the system.

I think this kernel function is locked (static ssize_t w1_slave_show(struct device *device,
struct device_attribute *attr, char *buf)) while this function (static void w1_therm_remove_slave(struct w1_slave *sl)) make a kfree on sl->family_data. And the locked function accesses to sl->family_data without checking if sl->family_data is to NULL.

Reference to linux-rpi-3.18.y\drivers\w1\slaves\w1_therm.c.

uname -a
Linux raspberrypi 3.18.8+ #765 PREEMPT Thu Mar 5 15:41:59 GMT 2015 armv6l GNU/Linux

Here is the dmesg:

[   66.375337] Unable to handle kernel NULL pointer dereference at virtual address 00000000
[   66.388108] pgd = da088000
[   66.392523] [00000000] *pgd=1a05c831, *pte=00000000, *ppte=00000000
[   66.401559] Internal error: Oops: 17 [#1] PREEMPT ARM
[   66.408247] Modules linked in: w1_therm w1_gpio wire cn uio_pdrv_genirq uio
[   66.417019] CPU: 0 PID: 2153 Comm: temperature Not tainted 3.18.8+ #765
[   66.425250] task: da04c380 ti: da24c000 task.ti: da24c000
[   66.432294] PC is at w1_slave_show+0x1e4/0x398 [w1_therm]
[   66.439337] LR is at 0x0
[   66.443491] pc : [<bf02e278>]    lr : [<00000000>]    psr: 60000013
[   66.443491] sp : da24de08  ip : 00000000  fp : da24de54
[   66.458308] r10: 000000c9  r9 : da24de27  r8 : da24de27
[   66.465187] r7 : db2ff050  r6 : da01d000  r5 : 00000fd9  r4 : 00000000
[   66.473406] r3 : 00000000  r2 : 00000001  r1 : 00000fd9  r0 : 00000027
[   66.481636] Flags: nZCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
[   66.490493] Control: 00c5387d  Table: 1a088008  DAC: 00000015
[   66.497964] Process temperature (pid: 2153, stack limit = 0xda24c1b0)
[   66.506165] Stack: (0xda24de08 to 0xda24e000)
[   66.512298] de00:                   bf02e5dc 00000000 00000000 db358094 db3bf0b0 ff3bf0b0
[   66.524049] de20: ffffffff ffffffff 00000001 da13dea0 bf02e704 da1af240 00001000 da01d000
[   66.535850] de40: c059a364 00000001 da24de6c da24de58 c03604cc bf02e0a0 da13dea0 db2ff058
[   66.547801] de60: da24de94 da24de70 c01aa708 c03604ac da13dea0 00000001 da24deb8 00000000
[   66.559825] de80: 00001000 db39daa0 da24dea4 da24de98 c01a9038 c01aa678 da24def4 da24dea8
[   66.571971] dea0: c015c210 c01a9010 da24c008 da13ded0 b6edc000 da24df78 00000000 00000000
[   66.584289] dec0: da24c028 00000000 da10dd80 da1af240 b6edc000 da24c000 da24df78 00001000
[   66.596756] dee0: b6edc000 00001000 da24df3c da24def8 c01a9a20 c015c064 da24df54 c0137d38
[   66.609408] df00: c01379d4 c0137784 00000001 da24df78 7fffffff db39daa0 b6edc000 da24c000
[   66.622180] df20: da24df78 00001000 b6edc000 00000000 da24df74 da24df40 c0137d64 c01a9908
[   66.635046] df40: da24df5c da24df50 c015525c 00000000 00000000 db39daa3 db39daa0 00001000
[   66.647971] df60: b6edc000 00000000 da24dfa4 da24df78 c0138478 c0137cd8 00000000 00000000
[   66.660898] df80: 01bda980 00000063 00000000 00000003 c000ea84 da24c000 00000000 da24dfa8
[   66.673848] dfa0: c000e800 c0138438 01bda980 00000063 00000004 b6edc000 00001000 00000000
[   66.686795] dfc0: 01bda980 00000063 00000000 00000003 b6c88d20 b6c88fb0 0000000a b6c88d20
[   66.699746] dfe0: 00000000 b6c88c08 b6d85ad8 b6d69ed4 80000010 00000004 00000000 00000000
[   66.712717] [<bf02e278>] (w1_slave_show [w1_therm]) from [<c03604cc>] (dev_attr_show+0x2c/0x58)
[   66.726222] [<c03604cc>] (dev_attr_show) from [<c01aa708>] (sysfs_kf_seq_show+0x9c/0x104)
[   66.739188] [<c01aa708>] (sysfs_kf_seq_show) from [<c01a9038>] (kernfs_seq_show+0x34/0x38)
[   66.752219] [<c01a9038>] (kernfs_seq_show) from [<c015c210>] (seq_read+0x1b8/0x488)
[   66.764619] [<c015c210>] (seq_read) from [<c01a9a20>] (kernfs_fop_read+0x124/0x16c)
[   66.776998] [<c01a9a20>] (kernfs_fop_read) from [<c0137d64>] (vfs_read+0x98/0x188)
[   66.789303] [<c0137d64>] (vfs_read) from [<c0138478>] (SyS_read+0x4c/0xa0)
[   66.798617] [<c0138478>] (SyS_read) from [<c000e800>] (ret_fast_syscall+0x0/0x48)
[   66.810686] Code: eb4ccaa4 e5173004 e2650a01 e1a01005 (e7d33004)
[   66.826414] ---[ end trace f2758d534129f3a2 ]---

Cheers,

Jonathan ALIBERT

[pelwell]

Can you explain what you mean by "while the device is deleted from the system"?

This sounds like a bug in the driver, which is something we take from the upstream kernel unmodified. Our resources are limited, so it is likely you will have to raise the bug with the authors and maintainers of the driver.

[Otherbright]

Ok, thank you for your answer, I will do it.

If I "hot unplug" the temperature probe while I read/wait the sys file /sys/bus/w1/devices/28-xxxxxxxxxxxx/w1_slave (select/read) this module bug appears. I think the one wire driver calls w1_therm_remove_slave before w1_slave_show terminates (I'm not a pro in driver development, but I assume this is that or is approaching the reason of the bug). Here are the two kernel functions of w1_therm which may cause the failure:

static void w1_therm_remove_slave(struct w1_slave *sl)
{
    kfree(sl->family_data);
    sl->family_data = NULL;
}

/* access to sl->family_data at the end of the function */
static ssize_t w1_slave_show(struct device *device,
    struct device_attribute *attr, char *buf)
{
    struct w1_slave *sl = dev_to_w1_slave(device);
    struct w1_master *dev = sl->master;
    u8 rom[9], crc, verdict, external_power;
    int i, max_trying = 10;
    ssize_t c = PAGE_SIZE;

    i = mutex_lock_interruptible(&dev->bus_mutex);
    if (i != 0)
        return i;

    memset(rom, 0, sizeof(rom));

    while (max_trying--) {

        verdict = 0;
        crc = 0;

        if (!w1_reset_select_slave(sl)) {
            int count = 0;
            unsigned int tm = 750;
            unsigned long sleep_rem;

            w1_write_8(dev, W1_READ_PSUPPLY);
            external_power = w1_read_8(dev);

            if (w1_reset_select_slave(sl))
                continue;

            /* 750ms strong pullup (or delay) after the convert */
            if (w1_strong_pullup == 2 ||
                    (!external_power && w1_strong_pullup))
                w1_next_pullup(dev, tm);

            w1_write_8(dev, W1_CONVERT_TEMP);

            if (external_power) {
                mutex_unlock(&dev->bus_mutex);

                sleep_rem = msleep_interruptible(tm);
                if (sleep_rem != 0)
                    return -EINTR;

                i = mutex_lock_interruptible(&dev->bus_mutex);
                if (i != 0)
                    return i;
            } else if (!w1_strong_pullup) {
                sleep_rem = msleep_interruptible(tm);
                if (sleep_rem != 0) {
                    mutex_unlock(&dev->bus_mutex);
                    return -EINTR;
                }
            }

            if (!w1_reset_select_slave(sl)) {

                w1_write_8(dev, W1_READ_SCRATCHPAD);
                if ((count = w1_read_block(dev, rom, 9)) != 9) {
                    dev_warn(device, "w1_read_block() "
                        "returned %u instead of 9.\n",
                        count);
                }

                crc = w1_calc_crc8(rom, 8);

                if (rom[8] == crc)
                    verdict = 1;
            }
        }

        if (verdict)
            break;
    }

    for (i = 0; i < 9; ++i)
        c -= snprintf(buf + PAGE_SIZE - c, c, "%02x ", rom[i]);
    c -= snprintf(buf + PAGE_SIZE - c, c, ": crc=%02x %s\n",
               crc, (verdict) ? "YES" : "NO");
    if (verdict)
        memcpy(sl->family_data, rom, sizeof(rom));
    else
        dev_warn(device, "Read failed CRC check\n");

    for (i = 0; i < 9; ++i)
        c -= snprintf(buf + PAGE_SIZE - c, c, "%02x ",
                  ((u8 *)sl->family_data)[i]);

    c -= snprintf(buf + PAGE_SIZE - c, c, "t=%d\n",
        w1_convert_temp(rom, sl->family->fid));
    mutex_unlock(&dev->bus_mutex);

    return PAGE_SIZE - c;
}

[Otherbright]

The module developer will patch the w1_temp.c file, and the bug is exactly what I was trying to explain. Simple solution : one mutex which disable the access to sl->family_data if w1_slave_show is running.

[pelwell]

Good work. Obviously we'll take the patch when it appears.

[nmgeek]

Was the patch applied? I can reproduce the bug in the 3.18.11+ kernel. And I am also tripping it in 4.0.7+

[pelwell]

It looks like the patch has been accepted upstream - it's in 4.2-rc1 here. Given that, we may be able to cherry-pick...

[nmgeek]

Thanks.
I apologize that I'm not part of the linux development culture so it's not clear to me how to cherry pick.

Do you mean to cherry pick a binary or cherry pick the source code. (I don't have an environment set up for building from source and wonder if it would take many, many hours to do that since the kernel model is distributed with the kernel.) If I grab the binary I guess I would need to find an apt repository for the rc version. Is there one?

[pelwell]

No apology needed - I was suggesting that we could back-port the patch. In fact I've already done that, and I'm in the process of trying to reproduce the problem so I can verify that it is fixed before submitting a Pull Request.

[pelwell]

I can't reproduce this - I'm on 4.0.7 on a Pi 2. How critical is the timing?

[pelwell]

To attack from the other direction, here is the patched w1_therm.ko compiled for 4.0.7-v7+ (i.e. Pi 2). If somebody can verify that this no longer crashes that would be helpful.

[nmgeek]

I'm not sure what to say about timing. Within two hours of booting up my Pi I usually get a kernel NULL pointer dereference.

I don't have a Pi 2. So maybe it's predictable that this binary leads to the following message in kern.log:

w1_therm: disagrees about version of symbol module_layout

I'm guessing the module_layout refers to compilation parameters and those are in the vermagic info which is different for the two versions of the compiled module:
My original module for Pi 1:

4.0.7+ preempt mod_unload mod versions ARMv6

Patched module for Pi 2:

4.0.7-v7+ SMP preempt mod_unload modversions ARMv7

If you compile it for Pi 1 (preempt ARMv6?) or show me how to do that then I'll give it a whirl.

[pelwell]

Pi 1 version here.

[nmgeek]

Excellent. It's running now. I'll report back in a day or so if it runs without exceptions.

[nmgeek]

No kernel faults yet

[dfries]

I developed the "w1_therm reference count family data" patch. In the original submission I explained that this is a band-aid patch, the final solution is expected to involve switching to the sysfs reference counting, while there is still a possibility for a race, my tests easily crash it without the patch, but not with it.

pelwell, this is my test, it simply has one loop manually adding and removing a device, and another trying to read that device, set the variable in multiple shells (giving one of your slave id's, or make one up), then run one loop for each shell, then after a while kill the add/remove. Other variations are to run multiple add/remove and or temperature read loops, but in general the add/remove loops have to be killed otherwise the reads get stuck and don't make progress.

slave=28-00000xxxxxxx

while true; do echo $slave > /sys/devices/w1_bus_master1/w1_master_add; sleep .1; echo $slave > /sys/devices/w1_bus_master1/w1_master_remove; sleep .1; done

while true; do time cat /sys/devices/w1_bus_master1/$slave/w1_slave ; sleep .1; done

[pelwell]

Thanks for that, David. With your test and without the patches I was able to easily recreate the problem. With the patches I haven't managed after trying for over an hour.

I've created PR #1059. If a better patch comes along we'll apply that instead, but for now this seems to solve the problem.

[nmgeek]

After 2 more days I have no kernel faults. I declare this patch a success.

[pelwell]

Great. I've merged the patches into 4.0.y, and I'll apply them to 4.1.y when my testing is complete.

[dfries]

As the patch is applied upstream anything further would be on top of this patch. Don't look for it in the near term, no one has volunteered to implement the lower level and more extensive changes Evgeniy Polyakov suggested.

I don't even use the w1_therm module anyway, I'm reading the temperature sensors over netlink, which is a non-blocking socket like interface, to the w1 driver. That lets my program send out 14 temperature conversion requests, delay, then issue 14 reads and collect the results, and be responsive to requests while it waits. With w1_therm every sysfs read blocks for the 750ms+ time it takes to do the above, so you either take 750*14 = 10.5 seconds to serially read one after another (and your program can't do anything else) or do multiple threads or processes, all of which is less efficient.

[Ruffio]

@jonalibert has your issue been resolved? If so, please close this issue. Thanks.

[JamesH65]

I believe the fix for this is merged from my reading above. Closing.