[Liunx][Kernel] Abort at __list_del_entry() inside process_one_work()

Debugging 

Kernel panic occurs at 68 line inside __list_del_entry() whose caller function is process_one_work().

Code Review at the moment of kernel panic

49void __list_del_entry(struct list_head *entry)

50{

51     struct list_head *prev, *next;

52

53     prev = entry->prev;

54     next = entry->next;

55

56    if (WARN(next == LIST_POISON1,

57                      "list_del corruption, %p->next is LIST_POISON1 (%p)\n",

58                      entry, LIST_POISON1) ||

59       WARN(prev == LIST_POISON2,

60                     "list_del corruption, %p->prev is LIST_POISON2 (%p)\n",

61                     entry, LIST_POISON2) ||

62      WARN(prev->next != entry,

63                    "list_del corruption. prev->next should be %p, "

64                    "but was %p\n", entry, prev->next) ||

65      WARN(next->prev != entry,

66                    "list_del corruption. next->prev should be %p, "

67                   "but was %p\n", entry, next->prev)) {

68                   BUG_ON(PANIC_CORRUPTION); // <<-- kernel panic

69     return;

70 }

71

72     __list_del(prev, next);

73}

Callstacks

-000|do_undefinstr(regs = 0x0)

-001|__und_svc_fault(asm)

-->|exception

-002|__list_del_entry(?) // <<-- kernel panic

-003|process_one_work(worker = 0xEC048600, work = 0xEA2585AC)

-004|worker_thread(__worker = 0x0)

-005|kthread(_create = 0xEB9B3000)

-006|ret_from_fork(asm)

-007|ret_fast_syscall(asm)

The list_del_init() is called inside process_one_work() whose parameter is &work->entry.

Now, it is important to debug the state of &work->entry

static void process_one_work(struct worker *worker, struct work_struct *work)

__releases(&pool->lock)

__acquires(&pool->lock)

{

    struct pool_workqueue *pwq = get_work_pwq(work);

    struct worker_pool *pool = worker->pool;

    bool cpu_intensive = pwq->wq->flags & WQ_CPU_INTENSIVE;

    int work_color;

    struct worker *collision;

//snip

/* claim and dequeue */

    debug_work_deactivate(work);

    hash_add(pool->busy_hash, &worker->hentry, (unsigned long)work);

    worker->current_work = work;

    worker->current_func = work->func;

    worker->current_pwq = pwq;

    work_color = get_work_color(work);

    list_del_init(&work->entry);

Going back to process_one_work() function frame using T32, I can have the following debug information

[1],[2]: next element is corrupted

[3]: worker.current_func is found to be irq_affinity_notify which looks abnormal.

process_one_work(

    worker = 0xEC048600 -> (

        entry = (next = 0x0, prev = 0xEC5AE968),

        hentry = (next = 0x0, pprev = 0xEC5AE968),

        current_work = 0xEA2585AC,

        current_func = 0xC016FD40,

        current_pwq = 0xEC5B2400,

        desc_valid = FALSE,

The memory content around 0xEC048600 seems to be corrupted especially for irq_affinity_notify at 0xEC04860C.

NSD:EC0485F8| 5A 5A 5A 5A 0x5A5A5A5A

NSD:EC0485FC| 5A 5A 5A 5A 0x5A5A5A5A

NSD:EC048600| 00 00 00 00 0x0 // <<--

NSD:EC048604| 68 E9 5A EC 0xEC5AE968

NSD:EC048608| AC 85 25 EA 0xEA2585AC

NSD:EC04860C| 40 FD 16 C0 0xC016FD40 \\vmlinux\manage\irq_affinity_notify // <<--

NSD:EC048610| 00 24 5B EC 0xEC5B2400

NSD:EC048614| 00 00 00 00 0x0

NSD:EC048618| 18 86 04 EC 0xEC048618

NSD:EC04861C| 18 86 04 EC 0xEC048618

NSD:EC048620| C0 57 2A EC 0xEC2A57C0

NSD:EC048624| 00 E8 5A EC 0xEC5AE800

NSD:EC048628| E8 E0 04 E9 0xE904E0E8

NSD:EC04862C| F0 E9 5A EC 0xEC5AE9F0

NSD:EC048630| AC 8D FF FF 0xFFFF8DAC

Searching "irq_affinity_notify" key word enables me to the definition of irq_affinity_notify structure.

struct irq_affinity_notify {

    unsigned int irq;

    struct kref kref;

    struct work_struct work;

    void (*notify)(struct irq_affinity_notify *, const cpumask_t *mask);

    void (*release)(struct kref *ref);

};

By casting 0xEA2585AC as struct work_struct, the following debug information can be deduced which looks very odd.

The struct work_struct.entry.next is corrupted as NULL and work_func_t is registered as irq_affinity_notify().

(struct work_struct *) [-] (struct work_struct*)0xEA2585AC = 0xEA2585AC = __bss_stop+0x2857B9A4 -> (

  (atomic_long_t) [D:0xEA2585AC] data = ((int) [D:0xEA2585AC] counter = -329571323 = 0xEC5B2405 = '.[

    (struct list_head) [D:0xEA2585B0] entry = (

    (struct list_head *) [D:0xEA2585B0] next = 0xE9E9EAB4 = __bss_stop+0x281C1EAC -> (

      (struct list_head *) [D:0xE9E9EAB4] next = 0x0 = -> NULL,

    (struct list_head *) [D:0xE9E9EAB8] prev = 0x0 = -> NULL),

  (struct list_head *) [D:0xEA2585B4] prev = 0xEC5AE820 = -> ((struct list_head *) [D:0xEC5AE820]

 (work_func_t) [D:0xEA2585B8] func = 0xC016FD40 = irq_affinity_notify -> )

Looking into the symbol information at 0xEA2585AC address, I can have the following symbols below.

(i.e) irq_affinity_notify, pm_qos_irq_notify, pm_qos_irq_release, pm_qos_work_fn

________address|_data________|value_____________|symbol

NSD:EA25859C| FF 00 00 00 0xFF \\vmlinux\Global\up_b_offset+0xCF

NSD:EA2585A0| 9D 00 00 00 0x9D \\vmlinux\Global\up_b_offset+0x6D

NSD:EA2585A4| 9D 00 00 00 0x9D \\vmlinux\Global\up_b_offset+0x6D

NSD:EA2585A8| 03 00 00 00 0x3

NSD:EA2585AC| 05 24 5B EC 0xEC5B2405

NSD:EA2585B0| B4 EA E9 E9 0xE9E9EAB4

NSD:EA2585B4| 20 E8 5A EC 0xEC5AE820

NSD:EA2585B8| 40 FD 16 C0 0xC016FD40 \\vmlinux\manage\irq_affinity_notify

NSD:EA2585BC| 58 90 16 C0 0xC0169058 \\vmlinux\kernel/power/qos\pm_qos_irq_notify

NSD:EA2585C0| 00 90 16 C0 0xC0169000 \\vmlinux\kernel/power/qos\pm_qos_irq_release

NSD:EA2585C4| 00 94 35 77 0x77359400

NSD:EA2585C8| C8 85 25 EA 0xEA2585C8

NSD:EA2585CC| C8 85 25 EA 0xEA2585C8

NSD:EA2585D0| 14 81 86 C1 0xC1868114 \\vmlinux\adreno\device_3d0+0x45C

NSD:EA2585D4| F8 C6 C4 E9 0xE9C4C6F8

NSD:EA2585D8| 01 00 00 00 0x1

NSD:EA2585DC| E0 FF FF FF 0xFFFFFFE0

NSD:EA2585E0| E0 85 25 EA 0xEA2585E0

NSD:EA2585E4| E0 85 25 EA 0xEA2585E0

NSD:EA2585E8| 10 8F 16 C0 0xC0168F10 \\vmlinux\kernel/power/qos\pm_qos_work_fn

NSD:EA2585EC| 00 00 00 00 0x0

NSD:EA2585F0| 00 00 00 00 0x0

NSD:EA2585F4| 00 00 00 00 0x0

NSD:EA2585F8| 02 00 B8 EB 0xEBB80002

NSD:EA2585FC| A8 77 13 C0 0xC01377A8 \\vmlinux\workqueue\delayed_work_timer_fn

NSD:EA258600| DC 85 25 EA 0xEA2585DC

When searching pm_qos_irq_notify in the kernel source code, I can see that pm_qos_irq_notify is registered as req->irq_notify.notify.

void pm_qos_add_request(struct pm_qos_request *req,

int pm_qos_class, s32 value)

{

//snip 

case PM_QOS_REQ_AFFINE_IRQ:

    if (irq_can_set_affinity(req->irq)) {

         int ret = 0;

         struct irq_desc *desc = irq_to_desc(req->irq);

         struct cpumask *mask = desc->irq_data.affinity;

         /* Get the current affinity */

         cpumask_copy(&req->cpus_affine, mask);

         req->irq_notify.irq = req->irq;

         req->irq_notify.notify = pm_qos_irq_notify;

         req->irq_notify.release = pm_qos_irq_release;

I can see that pm_qos_irq_notify() as well as pm_qos_irq_release() is registered as struct irq_affinity_notify.

struct irq_affinity_notify {

    unsigned int irq;

    struct kref kref;

    struct work_struct work;

    void (*notify)(struct irq_affinity_notify *, const cpumask_t *mask); // pm_qos_irq_notify

    void (*release)(struct kref *ref); // pm_qos_irq_release

};

struct pm_qos_request {

    enum pm_qos_req_type type;

    struct cpumask cpus_affine;

#ifdef CONFIG_SMP

    uint32_t irq;

/* Internal structure members */

    struct irq_affinity_notify irq_notify;

#endif

    struct plist_node node;

    int pm_qos_class;

    struct delayed_work work; /* for pm_qos_update_request_timeout */

};

The 0xEA2585A4 address is starting point where struct irq_affinity_notify element is located.

(struct irq_affinity_notify *) [-] (struct irq_affinity_notify*)0xEA2585A4

(unsigned int) [D:0xEA2585A4] irq = 157 = 0x9D = '....',

(struct kref) [D:0xEA2585A8] kref = (

   (atomic_t) [D:0xEA2585A8] refcount = ((int) [D:0xEA2585A8] counter = 3 = 0x3 = '....')),

(struct work_struct) [D:0xEA2585AC] work = (

   (atomic_long_t) [D:0xEA2585AC] data = ((int) [D:0xEA2585AC] counter = -329571323 = 0xEC5B2

   (struct list_head) [D:0xEA2585B0] entry = (

      (struct list_head *) [D:0xEA2585B0] next = 0xE9E9EAB4

      (struct list_head *) [D:0xEA2585B4] prev = 0xEC5AE820

   (work_func_t) [D:0xEA2585B8] func = 0xC016FD40 = irq_affinity_notify -> ),

   (void (*)()) [D:0xEA2585BC] notify = 0xC0169058 = pm_qos_irq_notify -> ,

   (void (*)()) [D:0xEA2585C0] release = 0xC0169000 = pm_qos_irq_release -> )

________address|_data________|value_____________|symbol

NSD:EA25859C| FF 00 00 00 0xFF \\vmlinux\Global\up_b_offset+0xCF

NSD:EA2585A0| 9D 00 00 00 0x9D \\vmlinux\Global\up_b_offset+0x6D

NSD:EA2585A4| 9D 00 00 00 0x9D //struct irq_affinity_notify.irq

NSD:EA2585A8| 03 00 00 00 0x3 //struct irq_affinity_notify.kref

NSD:EA2585AC| 05 24 5B EC 0xEC5B2405 //struct irq_affinity_notify.work.data

NSD:EA2585B0| B4 EA E9 E9 0xE9E9EAB4 //struct irq_affinity_notify.work.entry.next

NSD:EA2585B4| 20 E8 5A EC 0xEC5AE820 //struct irq_affinity_notify.work.entry.prev

NSD:EA2585B8| 40 FD 16 C0 0xC016FD40 \\vmlinux\manage\irq_affinity_notify //struct irq_affinity_notify.work.func

NSD:EA2585BC| 58 90 16 C0 0xC0169058 \\vmlinux\kernel/power/qos\pm_qos_irq_notify

NSD:EA2585C0| 00 90 16 C0 0xC0169000 \\vmlinux\kernel/power/qos\pm_qos_irq_release

NSD:EA2585C4| 00 94 35 77 0x77359400

NSD:EA2585C8| C8 85 25 EA 0xEA2585C8

NSD:EA2585CC| C8 85 25 EA 0xEA2585C8

NSD:EA2585D0| 14 81 86 C1 0xC1868114 \\vmlinux\adreno\device_3d0+0x45C

NSD:EA2585D4| F8 C6 C4 E9 0xE9C4C6F8

NSD:EA2585D8| 01 00 00 00 0x1

NSD:EA2585DC| E0 FF FF FF 0xFFFFFFE0

NSD:EA2585E0| E0 85 25 EA 0xEA2585E0

NSD:EA2585E4| E0 85 25 EA 0xEA2585E0

NSD:EA2585E8| 10 8F 16 C0 0xC0168F10 \\vmlinux\kernel/power/qos\pm_qos_work_fn

NSD:EA2585EC| 00 00 00 00 0x0

NSD:EA2585F0| 00 00 00 00 0x0

NSD:EA2585F4| 00 00 00 00 0x0

NSD:EA2585F8| 02 00 B8 EB 0xEBB80002

NSD:EA2585FC| A8 77 13 C0 0xC01377A8 \\vmlinux\workqueue\delayed_work_timer_fn

NSD:EA258600| DC 85 25 EA 0xEA2585DC

155: 1608 0 0 0 0 0 0 0 GIC mmc0

157: 98 0 0 0 0 0 0 0 GIC mmc1

166: 10 0 0 0 0 0 0 0 GIC msm_otg,msm_hsusb

Taking a looking at the structure associated with struct irq_affinity_notify,

struct pm_qos_request seems to include struct irq_affinity_notify irq_notify.

struct pm_qos_request {

    enum pm_qos_req_type type;

    struct cpumask cpus_affine;

#ifdef CONFIG_SMP

    uint32_t irq;

/* Internal structure members */

    struct irq_affinity_notify irq_notify;

#endif

    struct plist_node node;

    int pm_qos_class;

    struct delayed_work work; /* for pm_qos_update_request_timeout */

};

By casting 0xEA258598 as struct pm_qos_request, the whole picture is drawn as below.

(i.e) type = PM_QOS_REQ_AFFINE_IRQ

(struct pm_qos_request *) [-] (struct pm_qos_request*)0xEA258598 = 0xEA258598 = __bss_sto

  (enum pm_qos_req_type) [D:0xEA258598] type = PM_QOS_REQ_AFFINE_IRQ = 2 = 0x2 = '....',

  (struct cpumask) [D:0xEA25859C] cpus_affine = (

    (long unsigned int [1]) [D:0xEA25859C] bits = (

    [0] = 255 = 0xFF = '....')),

  (uint32_t) [D:0xEA2585A0] irq = 157 = 0x9D = '....',

  (struct irq_affinity_notify) [D:0xEA2585A4] irq_notify = ((unsigned int) [D:0xEA2585A4]  

  (struct plist_node) [D:0xEA2585C4] node = ((int) [D:0xEA2585C4] prio = 2000000000 = 0x7

  (int) [D:0xEA2585D8] pm_qos_class = 1 = 0x1 = '....',

  (struct delayed_work) [D:0xEA2585DC] work = (

   (struct work_struct) [D:0xEA2585DC] work = (

    (atomic_long_t) [D:0xEA2585DC] data = ((int) [D:0xEA2585DC] counter = -32 = 0xFFFFF

    (struct list_head) [D:0xEA2585E0] entry = ((struct list_head *) [D:0xEA2585E0] next

  (work_func_t) [D:0xEA2585E8] func = 0xC0168F10 = pm_qos_work_fn -> ),

  (struct timer_list) [D:0xEA2585EC] timer = ((struct list_head) [D:0xEA2585EC] entry =

 (struct workqueue_struct *) [D:0xEA258620] wq = 0x0 = -> NULL,

 (int) [D:0xEA258624] cpu = 0 = 0x0 = '....'))

(where)

________address|_data________|value_____________|symbol

NSD:EA258590| 00 00 00 00 0x0

NSD:EA258594| 01 00 00 00 0x1

NSD:EA258598| 02 00 00 00 0x2 //enum pm_qos_req_type type;

NSD:EA25859C| FF 00 00 00 0xFF //struct cpumask cpus_affine;

NSD:EA2585A0| 9D 00 00 00 0x9D //uint32_t irq;

NSD:EA2585A4| 9D 00 00 00 0x9D //struct irq_affinity_notify

NSD:EA2585A8| 03 00 00 00 0x3

NSD:EA2585AC| 05 24 5B EC 0xEC5B2405

NSD:EA2585B0| B4 EA E9 E9 0xE9E9EAB4

NSD:EA2585B4| 20 E8 5A EC 0xEC5AE820

NSD:EA2585B8| 40 FD 16 C0 0xC016FD40 \\vmlinux\manage\irq_affinity_notify

NSD:EA2585BC| 58 90 16 C0 0xC0169058 \\vmlinux\kernel/power/qos\pm_qos_irq_notify

NSD:EA2585C0| 00 90 16 C0 0xC0169000 \\vmlinux\kernel/power/qos\pm_qos_irq_release

NSD:EA2585C4| 00 94 35 77 0x77359400

NSD:EA2585C8| C8 85 25 EA 0xEA2585C8

NSD:EA2585CC| C8 85 25 EA 0xEA2585C8

NSD:EA2585D0| 14 81 86 C1 0xC1868114 \\vmlinux\adreno\device_3d0+0x45C

NSD:EA2585D4| F8 C6 C4 E9 0xE9C4C6F8

NSD:EA2585D8| 01 00 00 00 0x1

NSD:EA2585DC| E0 FF FF FF 0xFFFFFFE0

NSD:EA2585E0| E0 85 25 EA 0xEA2585E0

NSD:EA2585E4| E0 85 25 EA 0xEA2585E0

NSD:EA2585E8| 10 8F 16 C0 0xC0168F10 \\vmlinux\kernel/power/qos\pm_qos_work_fn

NSD:EA2585EC| 00 00 00 00 0x0

The (*(((struct pm_qos_request*)0xEA258598))).work.work.data is equal to 0xFFFFFFE0.

[-] (struct pm_qos_request*)0xEA258598 = 0xEA258598 -> (

//snip

D:0xEA2585DC] work = (

[D:0xEA2585DC] work = (

[D:0xEA2585DC] data = ([D:0xEA2585DC] counter = 0xFFFFFFE0), // <<-- WORK_STRUCT_NO_POOL

[D:0xEA2585E0] entry = ([D:0xEA2585E0] next = 0xEA2585E0, [D:0xEA2585E4] prev = 0xEA2585E0),

[D:0xEA2585E8] func = 0xC0168F10),

[D:0xEA2585EC] timer = ([D:0xEA2585EC] entry = ([D:0xEA2585EC] next = 0x0, [D:0xEA2585F0] prev = 0x0), [

[D:0xEA258620] wq = 0x0,

[D:0xEA258624] cpu = 0x0))

So it is needed to apply the following patch to see if the same crash occurs since 0xFFFFFFE0,

where 0xFFFFFFE0 = WORK_STRUCT_NO_POOL = (unsigned long)WORK_OFFQ_POOL_NONE << WORK_OFFQ_POOL_SHIFT,

diff --git a/kernel/power/qos.c b/kernel/power/qos.c

index 5f4c006..a122891 100644

--- a/kernel/power/qos.c

+++ b/kernel/power/qos.c

@@ -405,6 +405,9 @@ void pm_qos_update_request(struct pm_qos_request *req,

return;

}

+     if (work_is_canceling(&req->work) )

+        return;

+

      cancel_delayed_work_sync(&req->work);

      __pm_qos_update_request(req, new_value);

}

@@ -427,6 +430,9 @@ void pm_qos_update_request_timeout(struct pm_qos_request *req, s32 new_value,

"%s called for unknown object.", __func__))

return;

+     if (work_is_canceling(&req->work) )

+         return;

+

      cancel_delayed_work_sync(&req->work);

trace_pm_qos_update_request_timeout(req->pm_qos_class,

@@ -458,6 +464,9 @@ void pm_qos_remove_request(struct pm_qos_request *req)

return;

}

+     if (work_is_canceling(&req->work) )

+         return;

+

       cancel_delayed_work_sync(&req->work);

       trace_pm_qos_remove_request(req->pm_qos_class, PM_QOS_DEFAULT_VALUE);

static bool work_is_canceling(struct work_struct *work)

{

    unsigned long data = atomic_long_read(&work->data);

    return !(data & WORK_STRUCT_PWQ) && (data & WORK_OFFQ_CANCELING);

}

(where)

WORK_STRUCT_PWQ = 0x4, WORK_OFFQ_CANCELING = 0x10

In-depth Analysis

The work->data is set as WORK_STRUCT_NO_POOL inside clear_work_data() which is called from

static void clear_work_data(struct work_struct *work)

{

    smp_wmb(); /* see set_work_pool_and_clear_pending() */

    set_work_data(work, WORK_STRUCT_NO_POOL, 0);

}

static bool __cancel_work_timer(struct work_struct *work, bool is_dwork)

{

    static DECLARE_WAIT_QUEUE_HEAD(cancel_waitq);

    unsigned long flags;

    int ret;

    do {

        ret = try_to_grab_pending(work, is_dwork, &flags);

        if (unlikely(ret == -ENOENT)) {

               struct cwt_wait cwait;

               init_wait(&cwait.wait);

               cwait.wait.func = cwt_wakefn;

               cwait.work = work;

              prepare_to_wait_exclusive(&cancel_waitq, &cwait.wait,

              TASK_UNINTERRUPTIBLE);

              if (work_is_canceling(work))

                         schedule();

              finish_wait(&cancel_waitq, &cwait.wait);

      }

    } while (unlikely(ret < 0));

/* tell other tasks trying to grab @work to back off */ 

    mark_work_canceling(work);

    local_irq_restore(flags);

    flush_work(work); 

    clear_work_data(work); // <<--