2023-07-22 17:32:03

by Borislav Petkov

[permalink] [raw]
Subject: WARNING: CPU: 1 PID: 67 at drivers/ata/libata-core.c:1688 ata_read_log_page+0x173/0x1f0

Hi,

this is with Linus' tree from Thursday, top commit:

commit f7e3a1bafdea735050dfde00523cf505dc7fd309 (refs/remotes/origin/master, refs/remotes/origin/HEAD, refs/heads/master)
Merge: 12a5088eb138 28801cc85906
Author: Linus Torvalds <[email protected]>
Date: Thu Jul 20 20:35:38 2023 -0700

Merge tag 'drm-fixes-2023-07-21' of git://anongit.freedesktop.org/drm/drm

and tip/master merged ontop:

...
[ 3.435419] AVX version of gcm_enc/dec engaged.
[ 3.436188] AES CTR mode by8 optimization enabled
[ 4.181733] EXT4-fs (sdb2): mounted filesystem 1f347a17-b4a7-4d1c-bb60-5391961e8945 ro with ordered data mode. Quota mode: disabled.
[ 4.311786] ------------[ cut here ]------------
[ 4.312952] WARNING: CPU: 1 PID: 67 at drivers/ata/libata-core.c:1688 ata_read_log_page+0x173/0x1f0
[ 4.314124] Modules linked in: aesni_intel crypto_simd cryptd serio_raw thermal
[ 4.315296] CPU: 1 PID: 67 Comm: scsi_eh_2 Not tainted 6.5.0-rc2+ #1
[ 4.316483] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
[ 4.317653] RIP: 0010:ata_read_log_page+0x173/0x1f0
[ 4.318783] Code: ed 48 85 db 88 54 24 18 88 44 24 25 44 88 64 24 22 66 89 6c 24 20 44 88 74 24 1b 48 c7 44 24 10 07 00 00 00 0f 85 ee fe ff ff <0f> 0b e9 e7 fe ff ff 41 8b 4f 0c 81 e1 00 00 80 00 89 c8 f7 d8 18
[ 4.321370] RSP: 0018:ffffc90000cbbbc0 EFLAGS: 00010246
[ 4.322714] RAX: 0000000000000047 RBX: 0000000000000000 RCX: 0000000000000000
[ 4.324069] RDX: 0000000000000002 RSI: 000000000000000f RDI: 0000000000000400
[ 4.325401] RBP: 0000000000000f02 R08: 0000000000000002 R09: 0000000000000001
[ 4.326700] R10: 0000000000000000 R11: ffff888103cca290 R12: 0000000000000000
[ 4.328012] R13: 0000000000000001 R14: 0000000000000000 R15: ffff888104c02680
[ 4.329333] FS: 0000000000000000(0000) GS:ffff888211e80000(0000) knlGS:0000000000000000
[ 4.330652] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 4.331979] CR2: 00007f66683d99f0 CR3: 0000000002434005 CR4: 00000000001706e0
[ 4.333134] Call Trace:
[ 4.334239] <TASK>
[ 4.335323] ? ata_read_log_page+0x173/0x1f0
[ 4.336434] ? __warn+0x81/0x170
[ 4.337364] ? ata_read_log_page+0x173/0x1f0
[ 4.338270] ? report_bug+0x18d/0x1c0
[ 4.339170] ? handle_bug+0x3c/0x70
[ 4.340083] ? exc_invalid_op+0x13/0x60
[ 4.340917] ? asm_exc_invalid_op+0x16/0x20
[ 4.341732] ? ata_read_log_page+0x173/0x1f0
[ 4.342538] ? find_held_lock+0x2b/0x80
[ 4.343343] ata_eh_read_sense_success_ncq_log+0x3f/0x1c0
[ 4.344179] ata_eh_link_autopsy+0x7cd/0xc50
[ 4.344909] ata_eh_autopsy+0x26/0xd0
[ 4.345612] sata_pmp_error_handler+0x1e/0xa90
[ 4.346322] ? lock_acquire+0xb9/0x290
[ 4.347036] ? ata_wait_register+0x3f/0x90
[ 4.347779] ahci_error_handler+0x3e/0x70
[ 4.348435] ata_scsi_port_error_handler+0x37e/0x7e0
[ 4.349089] ? __pfx_scsi_error_handler+0x10/0x10
[ 4.349743] ata_scsi_error+0x93/0xc0
[ 4.350390] scsi_error_handler+0xb0/0x570
[ 4.351031] ? preempt_count_sub+0x9f/0xe0
[ 4.351685] ? _raw_spin_unlock_irqrestore+0x3b/0x60
[ 4.352271] ? __pfx_scsi_error_handler+0x10/0x10
[ 4.352835] kthread+0xf0/0x120
[ 4.353395] ? __pfx_kthread+0x10/0x10
[ 4.353949] ret_from_fork+0x30/0x50
[ 4.354502] ? __pfx_kthread+0x10/0x10
[ 4.355053] ret_from_fork_asm+0x1b/0x30
[ 4.355596] RIP: 0000:0x0
[ 4.356089] Code: Unable to access opcode bytes at 0xffffffffffffffd6.
[ 4.356570] RSP: 0000:0000000000000000 EFLAGS: 00000000 ORIG_RAX: 0000000000000000
[ 4.357053] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[ 4.357530] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[ 4.358000] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
[ 4.358462] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[ 4.358882] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 4.359262] </TASK>
[ 4.359632] irq event stamp: 1563
[ 4.359975] hardirqs last enabled at (1573): [<ffffffff81130652>] __up_console_sem+0x52/0x60
[ 4.360320] hardirqs last disabled at (1582): [<ffffffff81130637>] __up_console_sem+0x37/0x60
[ 4.360664] softirqs last enabled at (1010): [<ffffffff81bc6652>] __do_softirq+0x302/0x409
[ 4.361009] softirqs last disabled at (1001): [<ffffffff8109f8cf>] irq_exit_rcu+0x8f/0xf0
[ 4.361349] ---[ end trace 0000000000000000 ]---

--
Regards/Gruss,
Boris.

https://people.kernel.org/tglx/notes-about-netiquette


2023-07-24 08:02:59

by Hannes Reinecke

[permalink] [raw]
Subject: Re: WARNING: CPU: 1 PID: 67 at drivers/ata/libata-core.c:1688 ata_read_log_page+0x173/0x1f0

On 7/22/23 17:56, Borislav Petkov wrote:
> Hi,
>
> this is with Linus' tree from Thursday, top commit:
>
> commit f7e3a1bafdea735050dfde00523cf505dc7fd309 (refs/remotes/origin/master, refs/remotes/origin/HEAD, refs/heads/master)
> Merge: 12a5088eb138 28801cc85906
> Author: Linus Torvalds <[email protected]>
> Date: Thu Jul 20 20:35:38 2023 -0700
>
> Merge tag 'drm-fixes-2023-07-21' of git://anongit.freedesktop.org/drm/drm
>
> and tip/master merged ontop:
>
> ...
> [ 3.435419] AVX version of gcm_enc/dec engaged.
> [ 3.436188] AES CTR mode by8 optimization enabled
> [ 4.181733] EXT4-fs (sdb2): mounted filesystem 1f347a17-b4a7-4d1c-bb60-5391961e8945 ro with ordered data mode. Quota mode: disabled.
> [ 4.311786] ------------[ cut here ]------------
> [ 4.312952] WARNING: CPU: 1 PID: 67 at drivers/ata/libata-core.c:1688 ata_read_log_page+0x173/0x1f0
> [ 4.314124] Modules linked in: aesni_intel crypto_simd cryptd serio_raw thermal
> [ 4.315296] CPU: 1 PID: 67 Comm: scsi_eh_2 Not tainted 6.5.0-rc2+ #1
> [ 4.316483] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
> [ 4.317653] RIP: 0010:ata_read_log_page+0x173/0x1f0
> [ 4.318783] Code: ed 48 85 db 88 54 24 18 88 44 24 25 44 88 64 24 22 66 89 6c 24 20 44 88 74 24 1b 48 c7 44 24 10 07 00 00 00 0f 85 ee fe ff ff <0f> 0b e9 e7 fe ff ff 41 8b 4f 0c 81 e1 00 00 80 00 89 c8 f7 d8 18
> [ 4.321370] RSP: 0018:ffffc90000cbbbc0 EFLAGS: 00010246
> [ 4.322714] RAX: 0000000000000047 RBX: 0000000000000000 RCX: 0000000000000000
> [ 4.324069] RDX: 0000000000000002 RSI: 000000000000000f RDI: 0000000000000400
> [ 4.325401] RBP: 0000000000000f02 R08: 0000000000000002 R09: 0000000000000001
> [ 4.326700] R10: 0000000000000000 R11: ffff888103cca290 R12: 0000000000000000
> [ 4.328012] R13: 0000000000000001 R14: 0000000000000000 R15: ffff888104c02680
> [ 4.329333] FS: 0000000000000000(0000) GS:ffff888211e80000(0000) knlGS:0000000000000000
> [ 4.330652] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 4.331979] CR2: 00007f66683d99f0 CR3: 0000000002434005 CR4: 00000000001706e0
> [ 4.333134] Call Trace:
> [ 4.334239] <TASK>
> [ 4.335323] ? ata_read_log_page+0x173/0x1f0
> [ 4.336434] ? __warn+0x81/0x170
> [ 4.337364] ? ata_read_log_page+0x173/0x1f0
> [ 4.338270] ? report_bug+0x18d/0x1c0
> [ 4.339170] ? handle_bug+0x3c/0x70
> [ 4.340083] ? exc_invalid_op+0x13/0x60
> [ 4.340917] ? asm_exc_invalid_op+0x16/0x20
> [ 4.341732] ? ata_read_log_page+0x173/0x1f0
> [ 4.342538] ? find_held_lock+0x2b/0x80
> [ 4.343343] ata_eh_read_sense_success_ncq_log+0x3f/0x1c0
> [ 4.344179] ata_eh_link_autopsy+0x7cd/0xc50
> [ 4.344909] ata_eh_autopsy+0x26/0xd0
> [ 4.345612] sata_pmp_error_handler+0x1e/0xa90
> [ 4.346322] ? lock_acquire+0xb9/0x290
> [ 4.347036] ? ata_wait_register+0x3f/0x90
> [ 4.347779] ahci_error_handler+0x3e/0x70
> [ 4.348435] ata_scsi_port_error_handler+0x37e/0x7e0
> [ 4.349089] ? __pfx_scsi_error_handler+0x10/0x10
> [ 4.349743] ata_scsi_error+0x93/0xc0
> [ 4.350390] scsi_error_handler+0xb0/0x570
> [ 4.351031] ? preempt_count_sub+0x9f/0xe0
> [ 4.351685] ? _raw_spin_unlock_irqrestore+0x3b/0x60
> [ 4.352271] ? __pfx_scsi_error_handler+0x10/0x10
> [ 4.352835] kthread+0xf0/0x120
> [ 4.353395] ? __pfx_kthread+0x10/0x10
> [ 4.353949] ret_from_fork+0x30/0x50
> [ 4.354502] ? __pfx_kthread+0x10/0x10
> [ 4.355053] ret_from_fork_asm+0x1b/0x30
> [ 4.355596] RIP: 0000:0x0
> [ 4.356089] Code: Unable to access opcode bytes at 0xffffffffffffffd6.
> [ 4.356570] RSP: 0000:0000000000000000 EFLAGS: 00000000 ORIG_RAX: 0000000000000000
> [ 4.357053] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
> [ 4.357530] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
> [ 4.358000] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
> [ 4.358462] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
> [ 4.358882] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
> [ 4.359262] </TASK>
> [ 4.359632] irq event stamp: 1563
> [ 4.359975] hardirqs last enabled at (1573): [<ffffffff81130652>] __up_console_sem+0x52/0x60
> [ 4.360320] hardirqs last disabled at (1582): [<ffffffff81130637>] __up_console_sem+0x37/0x60
> [ 4.360664] softirqs last enabled at (1010): [<ffffffff81bc6652>] __do_softirq+0x302/0x409
> [ 4.361009] softirqs last disabled at (1001): [<ffffffff8109f8cf>] irq_exit_rcu+0x8f/0xf0
> [ 4.361349] ---[ end trace 0000000000000000 ]---
>
Does this help?

diff --git a/drivers/ata/libata-sata.c b/drivers/ata/libata-sata.c
index 85e279a12f62..db1334d04d9c 100644
--- a/drivers/ata/libata-sata.c
+++ b/drivers/ata/libata-sata.c
@@ -1492,6 +1492,10 @@ int ata_eh_read_sense_success_ncq_log(struct
ata_link *link)
continue;
}

+ if (WARN_ON(!qc->scsicmd)) {
+ qc->result_tf.status &= ~ATA_SENSE;
+ continue;
+ }
/* Set sense without also setting scsicmd->result */
scsi_build_sense_buffer(dev->flags & ATA_DFLAG_D_SENSE,
qc->scsicmd->sense_buffer, sk,


Cheers,

Hannes
--
Dr. Hannes Reinecke Kernel Storage Architect
[email protected] +49 911 74053 688
SUSE Software Solutions GmbH, Maxfeldstr. 5, 90409 Nürnberg
HRB 36809 (AG Nürnberg), Geschäftsführer: Ivo Totev, Andrew
Myers, Andrew McDonald, Martje Boudien Moerman


2023-07-24 12:05:31

by Borislav Petkov

[permalink] [raw]
Subject: Re: WARNING: CPU: 1 PID: 67 at drivers/ata/libata-core.c:1688 ata_read_log_page+0x173/0x1f0

+ hare.

On Mon, Jul 24, 2023 at 01:51:19PM +0200, Niklas Cassel wrote:
> Hello Boris,
>
> this is a null pointer dereference,
> because ap->ncq_sense_buf buffer is only allocated when CDL is enabled.
>
> We are not supposed to fetch sense data for successful NCQ commands when
> CDL is not enabled.
>
> This is my bad.
> Could you please test and see if this patch solves your problem:
> https://lore.kernel.org/linux-ide/[email protected]/

Yap, saw it, thanks.

I'll be able to get to it towards the end of the week.

Will let you know,

Thx.

--
Regards/Gruss,
Boris.

https://people.kernel.org/tglx/notes-about-netiquette

2023-07-24 12:07:33

by Niklas Cassel

[permalink] [raw]
Subject: Re: WARNING: CPU: 1 PID: 67 at drivers/ata/libata-core.c:1688 ata_read_log_page+0x173/0x1f0

On Sat, Jul 22, 2023 at 05:56:21PM +0200, Borislav Petkov wrote:
> Hi,
>
> this is with Linus' tree from Thursday, top commit:
>
> commit f7e3a1bafdea735050dfde00523cf505dc7fd309 (refs/remotes/origin/master, refs/remotes/origin/HEAD, refs/heads/master)
> Merge: 12a5088eb138 28801cc85906
> Author: Linus Torvalds <[email protected]>
> Date: Thu Jul 20 20:35:38 2023 -0700
>
> Merge tag 'drm-fixes-2023-07-21' of git://anongit.freedesktop.org/drm/drm
>
> and tip/master merged ontop:
>
> ...
> [ 3.435419] AVX version of gcm_enc/dec engaged.
> [ 3.436188] AES CTR mode by8 optimization enabled
> [ 4.181733] EXT4-fs (sdb2): mounted filesystem 1f347a17-b4a7-4d1c-bb60-5391961e8945 ro with ordered data mode. Quota mode: disabled.
> [ 4.311786] ------------[ cut here ]------------
> [ 4.312952] WARNING: CPU: 1 PID: 67 at drivers/ata/libata-core.c:1688 ata_read_log_page+0x173/0x1f0
> [ 4.314124] Modules linked in: aesni_intel crypto_simd cryptd serio_raw thermal
> [ 4.315296] CPU: 1 PID: 67 Comm: scsi_eh_2 Not tainted 6.5.0-rc2+ #1
> [ 4.316483] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
> [ 4.317653] RIP: 0010:ata_read_log_page+0x173/0x1f0
> [ 4.318783] Code: ed 48 85 db 88 54 24 18 88 44 24 25 44 88 64 24 22 66 89 6c 24 20 44 88 74 24 1b 48 c7 44 24 10 07 00 00 00 0f 85 ee fe ff ff <0f> 0b e9 e7 fe ff ff 41 8b 4f 0c 81 e1 00 00 80 00 89 c8 f7 d8 18
> [ 4.321370] RSP: 0018:ffffc90000cbbbc0 EFLAGS: 00010246
> [ 4.322714] RAX: 0000000000000047 RBX: 0000000000000000 RCX: 0000000000000000
> [ 4.324069] RDX: 0000000000000002 RSI: 000000000000000f RDI: 0000000000000400
> [ 4.325401] RBP: 0000000000000f02 R08: 0000000000000002 R09: 0000000000000001
> [ 4.326700] R10: 0000000000000000 R11: ffff888103cca290 R12: 0000000000000000
> [ 4.328012] R13: 0000000000000001 R14: 0000000000000000 R15: ffff888104c02680
> [ 4.329333] FS: 0000000000000000(0000) GS:ffff888211e80000(0000) knlGS:0000000000000000
> [ 4.330652] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 4.331979] CR2: 00007f66683d99f0 CR3: 0000000002434005 CR4: 00000000001706e0
> [ 4.333134] Call Trace:
> [ 4.334239] <TASK>
> [ 4.335323] ? ata_read_log_page+0x173/0x1f0
> [ 4.336434] ? __warn+0x81/0x170
> [ 4.337364] ? ata_read_log_page+0x173/0x1f0
> [ 4.338270] ? report_bug+0x18d/0x1c0
> [ 4.339170] ? handle_bug+0x3c/0x70
> [ 4.340083] ? exc_invalid_op+0x13/0x60
> [ 4.340917] ? asm_exc_invalid_op+0x16/0x20
> [ 4.341732] ? ata_read_log_page+0x173/0x1f0
> [ 4.342538] ? find_held_lock+0x2b/0x80
> [ 4.343343] ata_eh_read_sense_success_ncq_log+0x3f/0x1c0

Hello Boris,

this is a null pointer dereference,
because ap->ncq_sense_buf buffer is only allocated when CDL is enabled.

We are not supposed to fetch sense data for successful NCQ commands when
CDL is not enabled.

This is my bad.
Could you please test and see if this patch solves your problem:
https://lore.kernel.org/linux-ide/[email protected]/


Kind regards,
Niklas