crypto: sun4i-ss: error with kmap

+[  213.050152] ------------[ cut here ]------------
+[  213.050207] WARNING: CPU: 0 PID: 18430 at mm/highmem.c:581 kunmap_local_indexed+0x194/0x1d4
+[  213.050214] Modules linked in: sm4_generic authenc vmac xcbc hmac streebog_generic sm3_generic sha3_generic crct10dif_generic crct10dif_common seed rmd320 rmd256 rmd160 rmd128 cts lzo lzo_compress salsa20_generic camellia_generic fcrypt pcbc tgr192 anubis wp512 khazad tea michael_mic arc4 cast6_generic cast5_generic cast_common deflate zlib_deflate sha512_generic cfb ofb serpent_generic lrw twofish_generic twofish_common blowfish_generic blowfish_common md4
+[  213.050410] CPU: 0 PID: 18430 Comm: cryptsetup Not tainted 5.10.0-rc5-next-20201130-00059-gf7ecf0611042-dirty #242
+[  213.050416] Hardware name: Allwinner sun7i (A20) Family
+[  213.050448] [<c010d730>] (unwind_backtrace) from [<c010a218>] (show_stack+0x10/0x14)
+[  213.050465] [<c010a218>] (show_stack) from [<c08bbdcc>] (dump_stack+0x98/0xac)
+[  213.050479] [<c08bbdcc>] (dump_stack) from [<c08b93ac>] (__warn+0xc0/0xd8)
+[  213.050491] [<c08b93ac>] (__warn) from [<c08b9428>] (warn_slowpath_fmt+0x64/0xc0)
+[  213.050505] [<c08b9428>] (warn_slowpath_fmt) from [<c02018b4>] (kunmap_local_indexed+0x194/0x1d4)
+[  213.050525] [<c02018b4>] (kunmap_local_indexed) from [<c03e0390>] (sg_miter_stop+0xb4/0x164)
+[  213.050541] [<c03e0390>] (sg_miter_stop) from [<c03e082c>] (sg_miter_next+0xc/0xe4)
+[  213.050560] [<c03e082c>] (sg_miter_next) from [<c06b2d04>] (sun4i_ss_opti_poll+0x278/0x40c)
+[  213.050575] [<c06b2d04>] (sun4i_ss_opti_poll) from [<c06b338c>] (sun4i_ss_cipher_poll+0x4f4/0x5e4)
+[  213.050590] [<c06b338c>] (sun4i_ss_cipher_poll) from [<c03991d4>] (crypto_skcipher_encrypt+0x38/0x5c)
+[  213.050604] [<c03991d4>] (crypto_skcipher_encrypt) from [<c03aa980>] (xts_encrypt+0x8c/0xd4)
+[  213.050617] [<c03aa980>] (xts_encrypt) from [<c03991d4>] (crypto_skcipher_encrypt+0x38/0x5c)
+[  213.050631] [<c03991d4>] (crypto_skcipher_encrypt) from [<c03b3d94>] (skcipher_recvmsg+0x364/0x43c)
+[  213.050646] [<c03b3d94>] (skcipher_recvmsg) from [<c0719650>] (sock_read_iter+0xa8/0xf8)

+[  213.050663] [<c0719650>] (sock_read_iter) from [<c0239e98>] (vfs_read+0x2b8/0x2d8)
+[  213.050676] [<c0239e98>] (vfs_read) from [<c023a398>] (ksys_read+0xb0/0xe4)
+[  213.050688] [<c023a398>] (ksys_read) from [<c0100060>] (ret_fast_syscall+0x0/0x58)
+[  213.050695] Exception stack(0xc4d13fa8 to 0xc4d13ff0)
+[  213.050707] 3fa0:                   00000006 b6f084d0 00000006 b47ff000 00010000 00000000
+[  213.050718] 3fc0: 00000006 b6f084d0 00010000 00000003 00000030 beb6e9bc 00000010 beb6e9fc
+[  213.050727] 3fe0: b6e3609c beb6e958 b6cc8504 b6cc851c
+[  213.050735] ---[ end trace 915906e6b0e8a55d ]---

Quoted 19 lines · Corentin Labbe

+[  213.050152] ------------[ cut here ]------------
+[  213.050207] WARNING: CPU: 0 PID: 18430 at mm/highmem.c:581 kunmap_local_indexed+0x194/0x1d4
+[  213.050214] Modules linked in: sm4_generic authenc vmac xcbc hmac streebog_generic sm3_generic sha3_generic crct10dif_generic crct10dif_common seed rmd320 rmd256 rmd160 rmd128 cts lzo lzo_compress salsa20_generic camellia_generic fcrypt pcbc tgr192 anubis wp512 khazad tea michael_mic arc4 cast6_generic cast5_generic cast_common deflate zlib_deflate sha512_generic cfb ofb serpent_generic lrw twofish_generic twofish_common blowfish_generic blowfish_common md4
+[  213.050410] CPU: 0 PID: 18430 Comm: cryptsetup Not tainted 5.10.0-rc5-next-20201130-00059-gf7ecf0611042-dirty #242
+[  213.050416] Hardware name: Allwinner sun7i (A20) Family
+[  213.050448] [<c010d730>] (unwind_backtrace) from [<c010a218>] (show_stack+0x10/0x14)
+[  213.050465] [<c010a218>] (show_stack) from [<c08bbdcc>] (dump_stack+0x98/0xac)
+[  213.050479] [<c08bbdcc>] (dump_stack) from [<c08b93ac>] (__warn+0xc0/0xd8)
+[  213.050491] [<c08b93ac>] (__warn) from [<c08b9428>] (warn_slowpath_fmt+0x64/0xc0)
+[  213.050505] [<c08b9428>] (warn_slowpath_fmt) from [<c02018b4>] (kunmap_local_indexed+0x194/0x1d4)
+[  213.050525] [<c02018b4>] (kunmap_local_indexed) from [<c03e0390>] (sg_miter_stop+0xb4/0x164)
+[  213.050541] [<c03e0390>] (sg_miter_stop) from [<c03e082c>] (sg_miter_next+0xc/0xe4)
+[  213.050560] [<c03e082c>] (sg_miter_next) from [<c06b2d04>] (sun4i_ss_opti_poll+0x278/0x40c)
+[  213.050575] [<c06b2d04>] (sun4i_ss_opti_poll) from [<c06b338c>] (sun4i_ss_cipher_poll+0x4f4/0x5e4)
+[  213.050590] [<c06b338c>] (sun4i_ss_cipher_poll) from [<c03991d4>] (crypto_skcipher_encrypt+0x38/0x5c)
+[  213.050604] [<c03991d4>] (crypto_skcipher_encrypt) from [<c03aa980>] (xts_encrypt+0x8c/0xd4)
+[  213.050617] [<c03aa980>] (xts_encrypt) from [<c03991d4>] (crypto_skcipher_encrypt+0x38/0x5c)
+[  213.050631] [<c03991d4>] (crypto_skcipher_encrypt) from [<c03b3d94>] (skcipher_recvmsg+0x364/0x43c)
+[  213.050646] [<c03b3d94>] (skcipher_recvmsg) from [<c0719650>] (sock_read_iter+0xa8/0xf8)

Quoted 8 lines

+[  213.050663] [<c0719650>] (sock_read_iter) from [<c0239e98>] (vfs_read+0x2b8/0x2d8)
+[  213.050676] [<c0239e98>] (vfs_read) from [<c023a398>] (ksys_read+0xb0/0xe4)
+[  213.050688] [<c023a398>] (ksys_read) from [<c0100060>] (ret_fast_syscall+0x0/0x58)
+[  213.050695] Exception stack(0xc4d13fa8 to 0xc4d13ff0)
+[  213.050707] 3fa0:                   00000006 b6f084d0 00000006 b47ff000 00010000 00000000
+[  213.050718] 3fc0: 00000006 b6f084d0 00010000 00000003 00000030 beb6e9bc 00000010 beb6e9fc
+[  213.050727] 3fe0: b6e3609c beb6e958 b6cc8504 b6cc851c
+[  213.050735] ---[ end trace 915906e6b0e8a55d ]---

Hmm. No registers there. Can you apply the patch below so we can see the address?

Thanks,

tglx
---

mm/highmem.c +0 -0

index b49364a306b8..240fc6e5bfb4 100644
@@ -571,8 +571,10 @@ void kunmap_local_indexed(void *vaddr)
 		 * PAGE_OFFSET. Warn for all other addresses which are in

On Tue, Dec 01, 2020 at 02:28:54PM +0100, Thomas Gleixner wrote:
The patch made the board too busy logging and fail to boot until the test.

Quoted 2 lines · Corentin Labbe

On Tue, Dec 01, 2020 at 02:28:54PM +0100, Thomas Gleixner wrote:
The patch made the board too busy logging and fail to boot until the test.

Stupid me. Of course this wants to be conditional.

Thanks,

tglx
---

mm/highmem.c +0 -0

index b49364a306b8..178b126ab4f6 100644
@@ -571,8 +571,10 @@ void kunmap_local_indexed(void *vaddr)
 		 * PAGE_OFFSET. Warn for all other addresses which are in
 		 * the user space part of the virtual address space.

On Tue, Dec 01, 2020 at 03:16:36PM +0100, Thomas Gleixner wrote:
In fact the warn was a bit later so I added:

       preempt_disable();
        idx = arch_kmap_local_unmap_idx(kmap_local_idx(), addr);

(quoted diff) +2 -1

-       WARN_ON_ONCE(addr != __fix_to_virt(FIX_KMAP_BEGIN + idx));
+       if (WARN_ON_ONCE(addr != __fix_to_virt(FIX_KMAP_BEGIN + idx)))
+               pr_err("kunmap_local: vaddr %lx\n", (unsigned long) vaddr);
 
        arch_kmap_local_pre_unmap(addr);
        pte_clear(&init_mm, addr, kmap_pte - idx);

and this give kunmap_local: vaddr ffefe000

Quoted 11 lines · Corentin Labbe

On Tue, Dec 01, 2020 at 03:16:36PM +0100, Thomas Gleixner wrote:
In fact the warn was a bit later so I added:

       preempt_disable();
        idx = arch_kmap_local_unmap_idx(kmap_local_idx(), addr);

(quoted diff) +2 -1

-       WARN_ON_ONCE(addr != __fix_to_virt(FIX_KMAP_BEGIN + idx));
+       if (WARN_ON_ONCE(addr != __fix_to_virt(FIX_KMAP_BEGIN + idx)))
+               pr_err("kunmap_local: vaddr %lx\n", (unsigned long) vaddr);
 
        arch_kmap_local_pre_unmap(addr);
        pte_clear(&init_mm, addr, kmap_pte - idx);

Quoted 1 line

and this give kunmap_local: vaddr ffefe000

which looks like a valid one.

Can you apply the patch below and add 'ftrace_dump_on_oops' on the command line or enable it in /proc/sys/kernel/ftrace_dump_on_oops before starting the test.

That should spill out the trace after crashing.

Thanks,

tglx
---

mm/highmem.c +5 -1

index b49364a306b8..461fe2c26107 100644
@@ -485,6 +485,7 @@ static inline bool kmap_high_unmap_local(unsigned long vaddr)
 {
 #ifdef ARCH_NEEDS_KMAP_HIGH_GET
 	if (vaddr >= PKMAP_ADDR(0) && vaddr < PKMAP_ADDR(LAST_PKMAP)) {
+		trace_printk("kunmap_high: %lx\n", vaddr);
 		kunmap_high(pte_page(pkmap_page_table[PKMAP_NR(vaddr)]));
 		return true;
 	}

@@ -520,6 +521,7 @@ void *__kmap_local_pfn_prot(unsigned long pfn, pgprot_t prot)
 	preempt_disable();
 	idx = arch_kmap_local_map_idx(kmap_local_idx_push(), pfn);
 	vaddr = __fix_to_virt(FIX_KMAP_BEGIN + idx);
+	trace_printk("kmap_local_pfn: %d %lx\n", idx, (unsigned long) vaddr);
 	BUG_ON(!pte_none(*(kmap_pte - idx)));
 	pteval = pfn_pte(pfn, prot);
 	set_pte_at(&init_mm, vaddr, kmap_pte - idx, pteval);

@@ -545,8 +547,10 @@ void *__kmap_local_page_prot(struct page *page, pgprot_t prot)
 
 	/* Try kmap_high_get() if architecture has it enabled */
 	kmap = arch_kmap_local_high_get(page);
-	if (kmap)
+	if (kmap) {
+		trace_printk("kmap_local_high_get: %lx\n", (unsigned long) kmap);
 		return kmap;
+	}
 
 	return __kmap_local_pfn_prot(page_to_pfn(page), prot);
 }

On Tue, Dec 01, 2020 at 04:15:08PM +0100, Thomas Gleixner wrote:

The result could be seen at http://kernel.montjoie.ovh/129768.log
The log is 9Mb, but the ftrace dump seems not terminated, tell me if you need more.

Quoted 4 lines · Corentin Labbe

On Tue, Dec 01, 2020 at 04:15:08PM +0100, Thomas Gleixner wrote:

The result could be seen at http://kernel.montjoie.ovh/129768.log
The log is 9Mb, but the ftrace dump seems not terminated, tell me if you need more.

Correct, the interesting entries right before the crash are missing. Can you try to make the trace buffers smaller or wait longer before terminating the thing?

16k buffer size per CPU should be completely sufficient. That should give us roughly the last 100 entries per CPU.

'trace_buf_size=16k'

is the command line option for that.

Quoted 13 lines · Thomas Gleixner

Quoted 4 lines · Corentin Labbe

On Tue, Dec 01, 2020 at 04:15:08PM +0100, Thomas Gleixner wrote:

The result could be seen at http://kernel.montjoie.ovh/129768.log
The log is 9Mb, but the ftrace dump seems not terminated, tell me if you need more.

Correct, the interesting entries right before the crash are missing. Can you try to make the trace buffers smaller or wait longer before terminating the thing?

16k buffer size per CPU should be completely sufficient. That should give us roughly the last 100 entries per CPU.

Quoted 3 lines

'trace_buf_size=16k'

is the command line option for that.

I have set a longer timeout and now the job end with the crash:
http://kernel.montjoie.ovh/130094.log

Quoted 14 lines · Corentin Labbe

Quoted 13 lines · Thomas Gleixner

Quoted 4 lines · Corentin Labbe

On Tue, Dec 01, 2020 at 04:15:08PM +0100, Thomas Gleixner wrote:

The result could be seen at http://kernel.montjoie.ovh/129768.log
The log is 9Mb, but the ftrace dump seems not terminated, tell me if you need more.

Correct, the interesting entries right before the crash are missing. Can you try to make the trace buffers smaller or wait longer before terminating the thing?

16k buffer size per CPU should be completely sufficient. That should give us roughly the last 100 entries per CPU.

Quoted 6 lines

Quoted 3 lines

'trace_buf_size=16k'

is the command line option for that.

I have set a longer timeout and now the job end with the crash:
http://kernel.montjoie.ovh/130094.log

Ok. So here is the problem:

[  996.933980] cryptset-316       0d..3 73943313us : __kmap_local_pfn_prot: kmap_local_pfn: 0 ffefe000
[  996.943030] cryptset-316       0d..4 73943317us : __kmap_local_pfn_prot: kmap_local_pfn: 1 ffefd000
[  996.952080] cryptset-316       0d..4 73943419us : kunmap_local_indexed: kunmap_local: 1 ffefe000

There are two maps:

1) index 0 vaddr 0xffefe000
2) index 1 vaddr 0xffefd000

Now comes the unmap and unmaps 0xffefe000 which is the first map and not the second one. -> Fail

[   74.017103] [<c0251824>] (kunmap_local_indexed) from [<c046ca58>] (sg_miter_stop+0xb4/0x164)
[   74.025535] [<c046ca58>] (sg_miter_stop) from [<c046cef4>] (sg_miter_next+0xc/0xe4)
[   74.033191] [<c046cef4>] (sg_miter_next) from [<c075f5dc>] (sun4i_ss_opti_poll+0x278/0x40c)
[   74.041539] [<c075f5dc>] (sun4i_ss_opti_poll) from [<c075fc64>] (sun4i_ss_cipher_poll+0x4f4/0x5e4)
[   74.050497] [<c075fc64>] (sun4i_ss_cipher_poll) from [<c0421394>] (crypto_skcipher_encrypt+0x38/0x5c)
[   74.059713] [<c0421394>] (crypto_skcipher_encrypt) from [<c0432ba0>] (xts_encrypt+0x8c/0xd4)
[   74.068146] [<c0432ba0>] (xts_encrypt) from [<c0421394>] (crypto_skcipher_encrypt+0x38/0x5c)
[   74.076581] [<c0421394>] (crypto_skcipher_encrypt) from [<c043bfd4>] (skcipher_recvmsg+0x364/0x43c)
[   74.085625] [<c043bfd4>] (skcipher_recvmsg) from [<c07c8da0>] (sock_read_iter+0xa8/0xf8)
[   74.093713] [<c07c8da0>] (sock_read_iter) from [<c028ce94>] (vfs_read+0x2b8/0x2d8)
[   74.101279] [<c028ce94>] (vfs_read) from [<c028d394>] (ksys_read+0xb0/0xe4)
[   74.108237] [<c028d394>] (ksys_read) from [<c0100060>] (ret_fast_syscall+0x0/0x58)

The unmap comes from sg_miter_stop() and looking at the previous map/unmap cycles there are never nested maps.

[  996.943030] cryptset-316       0d..4 73943317us : __kmap_local_pfn_prot: kmap_local_pfn: 1 ffefd000

is the first event which allocates a nested map.

So something goes south either in sg_miter or in the crypto maze.

Enabling CONFIG_DEBUG_KMAP_LOCAL and function tracing might give us more clue.

Quoted 5 lines · Thomas Gleixner

The unmap comes from sg_miter_stop() and looking at the previous map/unmap cycles there are never nested maps.

[  996.943030] cryptset-316       0d..4 73943317us : __kmap_local_pfn_prot: kmap_local_pfn: 1 ffefd000

Quoted 5 lines

is the first event which allocates a nested map.

So something goes south either in sg_miter or in the crypto maze.

Enabling CONFIG_DEBUG_KMAP_LOCAL and function tracing might give us more clue.

Done, http://kernel.montjoie.ovh/130466.log

Quoted 10 lines · Corentin Labbe

Quoted 9 lines · Thomas Gleixner

The unmap comes from sg_miter_stop() and looking at the previous map/unmap cycles there are never nested maps.

[  996.943030] cryptset-316       0d..4 73943317us : __kmap_local_pfn_prot: kmap_local_pfn: 1 ffefd000

is the first event which allocates a nested map.

So something goes south either in sg_miter or in the crypto maze.

Quoted 3 lines

Quoted 1 line

Enabling CONFIG_DEBUG_KMAP_LOCAL and function tracing might give us more clue.

Done, http://kernel.montjoie.ovh/130466.log

Does not provide more information with the debug enabled. So can you please enable CONFIG_FUNCTION_TRACER and add 'ftrace=function' to the command line?

Quoted 13 lines · Thomas Gleixner

Quoted 12 lines · Corentin Labbe

Quoted 10 lines · Thomas Gleixner

The unmap comes from sg_miter_stop() and looking at the previous map/unmap cycles there are never nested maps.

[  996.943030] cryptset-316       0d..4 73943317us : __kmap_local_pfn_prot: kmap_local_pfn: 1 ffefd000

is the first event which allocates a nested map.

So something goes south either in sg_miter or in the crypto maze.

Enabling CONFIG_DEBUG_KMAP_LOCAL and function tracing might give us more clue.

Quoted 5 lines

Quoted 1 line

Done, http://kernel.montjoie.ovh/130466.log

Does not provide more information with the debug enabled. So can you please enable CONFIG_FUNCTION_TRACER and add 'ftrace=function' to the command line?

Done, http://kernel.montjoie.ovh/130490.log

Quoted 14 lines · Corentin Labbe

Quoted 13 lines · Thomas Gleixner

Quoted 12 lines · Corentin Labbe

Quoted 10 lines · Thomas Gleixner

The unmap comes from sg_miter_stop() and looking at the previous map/unmap cycles there are never nested maps.

[  996.943030] cryptset-316       0d..4 73943317us : __kmap_local_pfn_prot: kmap_local_pfn: 1 ffefd000

is the first event which allocates a nested map.

So something goes south either in sg_miter or in the crypto maze.

Enabling CONFIG_DEBUG_KMAP_LOCAL and function tracing might give us more clue.

Quoted 7 lines

Quoted 5 lines

Quoted 1 line

Done, http://kernel.montjoie.ovh/130466.log

Does not provide more information with the debug enabled. So can you please enable CONFIG_FUNCTION_TRACER and add 'ftrace=function' to the command line?

Done, http://kernel.montjoie.ovh/130490.log

Aaargh. That overwrites everything while printing out that warning.

Can you please replace the debug patch with the one below and try again? That stops the trace right on the condition.

Thanks,

tglx
---

mm/highmem.c +5 -1

index b49364a306b8..8f8862f79d23 100644
@@ -485,6 +485,7 @@ static inline bool kmap_high_unmap_local(unsigned long vaddr)
 {
 #ifdef ARCH_NEEDS_KMAP_HIGH_GET
 	if (vaddr >= PKMAP_ADDR(0) && vaddr < PKMAP_ADDR(LAST_PKMAP)) {
+		trace_printk("kunmap_high: %lx\n", vaddr);
 		kunmap_high(pte_page(pkmap_page_table[PKMAP_NR(vaddr)]));
 		return true;
 	}

@@ -520,6 +521,7 @@ void *__kmap_local_pfn_prot(unsigned long pfn, pgprot_t prot)
 	preempt_disable();
 	idx = arch_kmap_local_map_idx(kmap_local_idx_push(), pfn);
 	vaddr = __fix_to_virt(FIX_KMAP_BEGIN + idx);
+	trace_printk("kmap_local_pfn: %d %lx\n", idx, (unsigned long) vaddr);
 	BUG_ON(!pte_none(*(kmap_pte - idx)));
 	pteval = pfn_pte(pfn, prot);
 	set_pte_at(&init_mm, vaddr, kmap_pte - idx, pteval);

@@ -545,8 +547,10 @@ void *__kmap_local_page_prot(struct page *page, pgprot_t prot)
 
 	/* Try kmap_high_get() if architecture has it enabled */
 	kmap = arch_kmap_local_high_get(page);
-	if (kmap)
+	if (kmap) {
+		trace_printk("kmap_local_high_get: %lx\n", (unsigned long) kmap);
 		return kmap;
+	}
 
 	return __kmap_local_pfn_prot(page_to_pfn(page), prot);
 }

@@ -578,7 +582,11 @@ void kunmap_local_indexed(void *vaddr)
 
 	preempt_disable();

Quoted 2 lines · Thomas Gleixner

Can you please replace the debug patch with the one below and try again? That stops the trace right on the condition.

Hello, the result could be found at http://kernel.montjoie.ovh/130739.log

Corentin,

Quoted 5 lines · Corentin Labbe

Quoted 2 lines · Thomas Gleixner

Can you please replace the debug patch with the one below and try again? That stops the trace right on the condition.

Hello, the result could be found at http://kernel.montjoie.ovh/130739.log

Thanks for providing this. This is clearly showing where stuff goes wrong. It starts here at 729.550001. I removed the uninteresting parts:

0d..2 147103293us : __kmap_local_page_prot <-sg_miter_next 0d..3 147103308us :__kmap_local_pfn_prot: kmap_local_pfn: 1 ffefd000

0d..3 147103311us : __kmap_local_page_prot <-sg_miter_next 0d..4 147103325us : __kmap_local_pfn_prot: kmap_local_pfn: 3 ffefb000

0d..3 147103429us : kunmap_local_indexed <-sg_miter_stop 0d..4 147103433us : kunmap_local_indexed: kunmap_local: 3 ffefd000

So this maps two pages and unmaps the first one. That's all called from sun4i_ss_opti_poll() and the bug is clearly visible there:

	sg_miter_next(&mi);
	sg_miter_next(&mo);

release_ss:

	sg_miter_stop(&mi);
	sg_miter_stop(&mo);

Written by yourself :) Same issue in sun4i_ss_cipher_poll()

Fix below.

Julia, it might be worth to have a coccinelle check for that. It's the only place which got it wrong, but this goes unnoticed when code is e.g. only fully tested on 64bit or as in this case never tested with full debugging enabled. The whole kmap_atomic and kmap_local (new in next) family and all users like the sg_miter stuff are affected by this.

Thanks,

tglx
---
Subject: crypto: sun4i-ss - Fix sg_miter_stop() ordering
From: Thomas Gleixner <[email protected]>
Date: Sat, 05 Dec 2020 20:17:28 +0100

sun4i_ss_opti_poll() and sun4i_ss_cipher_poll() do:

        sg_miter_next(&mi);
        sg_miter_next(&mo);
	...
        sg_miter_stop(&mi);
        sg_miter_stop(&mo);

which is the wrong order because sg_miter_next() maps a page with kmap_atomic() and sg_miter_stop() unmaps it. kmap_atomic() uses a stack internaly which requires that the nested map is unmapped first. As this uses the wrong order it triggers the warning in kunmap_local_indexed() which checks the to be unmapped address and subsequently crashes.

This went unnoticed for 5 years because the ARM kmap_atomic() implementation had the warning conditional on CONFIG_DEBUG_HIGHMEM which was obviously never enabled when testing that driver.

Flip the order to cure it.

Reported-by Corentin Labbe <[email protected]>

Fixes 6298e948215f ("crypto: sunxi-ss - Add Allwinner Security System crypto accelerator")

Signed-off-by Thomas Gleixner <[email protected]>

Cc [email protected]

---
 drivers/crypto/allwinner/sun4i-ss/sun4i-ss-cipher.c |    4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

drivers/crypto/allwinner/sun4i-ss/sun4i-ss-cipher.c +2 -2

@@ -109,8 +109,8 @@ static int noinline_for_stack sun4i_ss_o
 	}
 
 release_ss:
-	sg_miter_stop(&mi);
 	sg_miter_stop(&mo);
+	sg_miter_stop(&mi);
 	writel(0, ss->base + SS_CTL);
 	spin_unlock_irqrestore(&ss->slock, flags);
 	return err;

@@ -333,8 +333,8 @@ static int sun4i_ss_cipher_poll(struct s
 	}
 
 release_ss:
-	sg_miter_stop(&mi);
 	sg_miter_stop(&mo);
+	sg_miter_stop(&mi);
 	writel(0, ss->base + SS_CTL);
 	spin_unlock_irqrestore(&ss->slock, flags);
 

Corentin,

Quoted 5 lines · Corentin Labbe

Quoted 2 lines · Thomas Gleixner

Can you please replace the debug patch with the one below and try again? That stops the trace right on the condition.

Hello, the result could be found at http://kernel.montjoie.ovh/130739.log

Thanks for providing this. This is clearly showing where stuff goes wrong. It starts here at 729.550001. I removed the uninteresting parts:

0d..2 147103293us : __kmap_local_page_prot <-sg_miter_next 0d..3 147103308us :__kmap_local_pfn_prot: kmap_local_pfn: 1 ffefd000

0d..3 147103311us : __kmap_local_page_prot <-sg_miter_next 0d..4 147103325us : __kmap_local_pfn_prot: kmap_local_pfn: 3 ffefb000

0d..3 147103429us : kunmap_local_indexed <-sg_miter_stop 0d..4 147103433us : kunmap_local_indexed: kunmap_local: 3 ffefd000

So this maps two pages and unmaps the first one. That's all called from sun4i_ss_opti_poll() and the bug is clearly visible there:

	sg_miter_next(&mi);
	sg_miter_next(&mo);

release_ss:

	sg_miter_stop(&mi);
	sg_miter_stop(&mo);

Written by yourself :) Same issue in sun4i_ss_cipher_poll()

Fix below.

Quoted 10 lines · Thomas Gleixner

So this maps two pages and unmaps the first one. That's all called from sun4i_ss_opti_poll() and the bug is clearly visible there:

	sg_miter_next(&mi);
	sg_miter_next(&mo);

release_ss:

	sg_miter_stop(&mi);
	sg_miter_stop(&mo);

Quoted 4 lines

Written by yourself :) Same issue in sun4i_ss_cipher_poll()

Fix below.

Unfortunatly, the crash still happen with the fix. See http://kernel.montjoie.ovh/131321.log

Quoted 11 lines · Corentin Labbe

Quoted 10 lines · Thomas Gleixner

So this maps two pages and unmaps the first one. That's all called from sun4i_ss_opti_poll() and the bug is clearly visible there:

	sg_miter_next(&mi);
	sg_miter_next(&mo);

release_ss:

	sg_miter_stop(&mi);
	sg_miter_stop(&mo);

Quoted 7 lines

Quoted 4 lines

Written by yourself :) Same issue in sun4i_ss_cipher_poll()

Fix below.

Unfortunatly, the crash still happen with the fix. See http://kernel.montjoie.ovh/131321.log

And why are you not looking for the reason of this problem in your own code yourself? It's not a regression caused by my work.

Turn on CONFIG_DEBUG_HIGHMEM on 5.10-rcX or older kernels and you will get the very same crashes. My work just made these checks unconditional.

This was broken forever and it's not my problem that you did not enable mandatory debug options when developing this thing.

I gave you tons of hints by now how to debug this and what to look for. Obviously I overlooked something and here is the final hint:

(quoted diff) +0 -0

 	sg_miter_next(&mi);
 	sg_miter_next(&mo);
 
        do {
....
           if (cond1)
               sg_miter_next(&mi);      <--- HINT
....
           if (cond2)
               sg_miter_next(&mo);

release_ss:

(quoted diff) +0 -0

 	sg_miter_stop(&mi);
 	sg_miter_stop(&mo);

So yes, I overlooked the obvious, but as I said above it's not something which my is failing due to my changes. It was broken forever, it just was not tested properly. Don't blame the messenger.

On Mon, Dec 07, 2020 at 01:15:49AM +0100, Thomas Gleixner wrote:

So if I understand correctly, basicly I cannot have two atomic kmap at the same time since it made unmapping them in the right order complex.

I am not sure to have well understood your hint, but could you give me

what you think about the following patch which fix (at least) the crash. Instead of holding SGmiter (and so two kmap), I use only one at a time.