Re: crypto: sun4i-ss: error with kmap

Re: crypto: sun4i-ss: error with kmap

[Thomas Gleixner]

On Thu, Dec 03 2020 at 18:38, Corentin Labbe wrote:
> On Wed, Dec 02, 2020 at 09:59:36PM +0100, Thomas Gleixner wrote:
>> On Wed, Dec 02 2020 at 20:55, Corentin Labbe wrote:
>> > 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.
>
> 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.

Thanks,

        tglx

Re: crypto: sun4i-ss: error with kmap

[Corentin Labbe]

On Fri, Dec 04, 2020 at 12:34:05AM +0100, Thomas Gleixner wrote:
> On Thu, Dec 03 2020 at 18:38, Corentin Labbe wrote:
> > On Wed, Dec 02, 2020 at 09:59:36PM +0100, Thomas Gleixner wrote:
> >> On Wed, Dec 02 2020 at 20:55, Corentin Labbe wrote:
> >> > 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.
> >
> > 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.

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

Re: crypto: sun4i-ss: error with kmap

[Thomas Gleixner]

On Fri, Dec 04 2020 at 14:26, Corentin Labbe wrote:
> On Fri, Dec 04, 2020 at 12:34:05AM +0100, Thomas Gleixner wrote:
>> 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.
>
> 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?

Thanks,

        tglx

Re: crypto: sun4i-ss: error with kmap

[Corentin Labbe]

On Fri, Dec 04, 2020 at 04:08:27PM +0100, Thomas Gleixner wrote:
> On Fri, Dec 04 2020 at 14:26, Corentin Labbe wrote:
> > On Fri, Dec 04, 2020 at 12:34:05AM +0100, Thomas Gleixner wrote:
> >> 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.
> >
> > 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

Re: crypto: sun4i-ss: error with kmap

[Thomas Gleixner]

On Fri, Dec 04 2020 at 20:27, Corentin Labbe wrote:
> On Fri, Dec 04, 2020 at 04:08:27PM +0100, Thomas Gleixner wrote:
>> On Fri, Dec 04 2020 at 14:26, Corentin Labbe wrote:
>> > On Fri, Dec 04, 2020 at 12:34:05AM +0100, Thomas Gleixner wrote:
>> >> 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.
>> >
>> > 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
---
diff --git a/mm/highmem.c b/mm/highmem.c
index b49364a306b8..8f8862f79d23 100644
--- a/mm/highmem.c
+++ b/mm/highmem.c
@@ -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();
 	idx = arch_kmap_local_unmap_idx(kmap_local_idx(), addr);
-	WARN_ON_ONCE(addr != __fix_to_virt(FIX_KMAP_BEGIN + idx));
+	trace_printk("kunmap_local: %i %lx\n", idx, (unsigned long) vaddr);
+	if (addr != __fix_to_virt(FIX_KMAP_BEGIN + idx)) {
+		tracing_off();
+		BUG();
+	}
 
 	arch_kmap_local_pre_unmap(addr);
 	pte_clear(&init_mm, addr, kmap_pte - idx);

Re: crypto: sun4i-ss: error with kmap

[Corentin Labbe]

On Fri, Dec 04, 2020 at 09:58:21PM +0100, Thomas Gleixner wrote:
> On Fri, Dec 04 2020 at 20:27, Corentin Labbe wrote:
> > On Fri, Dec 04, 2020 at 04:08:27PM +0100, Thomas Gleixner wrote:
> >> On Fri, Dec 04 2020 at 14:26, Corentin Labbe wrote:
> >> > On Fri, Dec 04, 2020 at 12:34:05AM +0100, Thomas Gleixner wrote:
> >> >> 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.
> >> >
> >> > 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
> ---
> diff --git a/mm/highmem.c b/mm/highmem.c
> index b49364a306b8..8f8862f79d23 100644
> --- a/mm/highmem.c
> +++ b/mm/highmem.c
> @@ -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();
>  	idx = arch_kmap_local_unmap_idx(kmap_local_idx(), addr);
> -	WARN_ON_ONCE(addr != __fix_to_virt(FIX_KMAP_BEGIN + idx));
> +	trace_printk("kunmap_local: %i %lx\n", idx, (unsigned long) vaddr);
> +	if (addr != __fix_to_virt(FIX_KMAP_BEGIN + idx)) {
> +		tracing_off();
> +		BUG();
> +	}
>  
>  	arch_kmap_local_pre_unmap(addr);
>  	pte_clear(&init_mm, addr, kmap_pte - idx);
> 

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

Thanks

Re: crypto: sun4i-ss: error with kmap

[Thomas Gleixner]

Corentin,

On Sat, Dec 05 2020 at 19:43, Corentin Labbe wrote:
> On Fri, Dec 04, 2020 at 09:58:21PM +0100, Thomas Gleixner wrote:
>> 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 <tglx@linutronix.de>
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 <clabbe.montjoie@gmail.com>
Fixes: 6298e948215f ("crypto: sunxi-ss - Add Allwinner Security System crypto accelerator")
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
Cc: stable@vger.kernel.org
---
 drivers/crypto/allwinner/sun4i-ss/sun4i-ss-cipher.c |    4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

--- a/drivers/crypto/allwinner/sun4i-ss/sun4i-ss-cipher.c
+++ b/drivers/crypto/allwinner/sun4i-ss/sun4i-ss-cipher.c
@@ -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);
 

Re: crypto: sun4i-ss: error with kmap

[Julia Lawall]

On Sat, 5 Dec 2020, Thomas Gleixner wrote:

> Corentin,
>
> On Sat, Dec 05 2020 at 19:43, Corentin Labbe wrote:
> > On Fri, Dec 04, 2020 at 09:58:21PM +0100, Thomas Gleixner wrote:
> >> 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.

OK, thanks for the suggestion.  I will look into it.

julia

>
> Thanks,
>
>         tglx
> ---
> Subject: crypto: sun4i-ss - Fix sg_miter_stop() ordering
> From: Thomas Gleixner <tglx@linutronix.de>
> 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 <clabbe.montjoie@gmail.com>
> Fixes: 6298e948215f ("crypto: sunxi-ss - Add Allwinner Security System crypto accelerator")
> Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
> Cc: stable@vger.kernel.org
> ---
>  drivers/crypto/allwinner/sun4i-ss/sun4i-ss-cipher.c |    4 ++--
>  1 file changed, 2 insertions(+), 2 deletions(-)
>
> --- a/drivers/crypto/allwinner/sun4i-ss/sun4i-ss-cipher.c
> +++ b/drivers/crypto/allwinner/sun4i-ss/sun4i-ss-cipher.c
> @@ -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);
>
>
>
>

Re: crypto: sun4i-ss: error with kmap

[Corentin Labbe]

On Sat, Dec 05, 2020 at 08:48:15PM +0100, Thomas Gleixner wrote:
> Corentin,
> 
> On Sat, Dec 05 2020 at 19:43, Corentin Labbe wrote:
> > On Fri, Dec 04, 2020 at 09:58:21PM +0100, Thomas Gleixner wrote:
> >> 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.
> 

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

Re: crypto: sun4i-ss: error with kmap

[Thomas Gleixner]

On Sun, Dec 06 2020 at 22:40, Corentin Labbe wrote:
> On Sat, Dec 05, 2020 at 08:48:15PM +0100, Thomas Gleixner wrote:
>> 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.
>> 
>
> 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:

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

        do {
           ....
           if (cond1)
               sg_miter_next(&mi);      <--- HINT
           ....
           if (cond2)
               sg_miter_next(&mo);
 
release_ss:
 	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.

My knowledge about how to use nested sg_miter correctly is close to
zero. I can and did explain you the rules of kmap_atomic/local() but
that's it.

Thanks,

        tglx

Re: crypto: sun4i-ss: error with kmap

[Corentin Labbe]

On Mon, Dec 07, 2020 at 01:15:49AM +0100, Thomas Gleixner wrote:
> On Sun, Dec 06 2020 at 22:40, Corentin Labbe wrote:
> > On Sat, Dec 05, 2020 at 08:48:15PM +0100, Thomas Gleixner wrote:
> >> 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.
> >> 
> >
> > 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:
> 
>  	sg_miter_next(&mi);
>  	sg_miter_next(&mo);
> 
>         do {
>            ....
>            if (cond1)
>                sg_miter_next(&mi);      <--- HINT
>            ....
>            if (cond2)
>                sg_miter_next(&mo);
>  
> release_ss:
>  	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.
> 

Hello

I wasnt blaming you, I set you in TO: since you worked on kmap recently just in case of.
I tryed to debug myself, but since it worked before I was sure the problem was outside my code.

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.

Thanks for your help.

diff --git a/drivers/crypto/allwinner/sun4i-ss/sun4i-ss-cipher.c b/drivers/crypto/allwinner/sun4i-ss/sun4i-ss-cipher.c
index 99a415e8a13c..4f25e76dc269 100644
--- a/drivers/crypto/allwinner/sun4i-ss/sun4i-ss-cipher.c
+++ b/drivers/crypto/allwinner/sun4i-ss/sun4i-ss-cipher.c
@@ -36,6 +36,8 @@ static int noinline_for_stack sun4i_ss_opti_poll(struct skcipher_request *areq)
 	unsigned long flags;
 	struct skcipher_alg *alg = crypto_skcipher_alg(tfm);
 	struct sun4i_ss_alg_template *algt;
+	unsigned long toi = 0, too = 0;
+	bool miter_err;
 
 	if (!areq->cryptlen)
 		return 0;
@@ -71,39 +73,51 @@ static int noinline_for_stack sun4i_ss_opti_poll(struct skcipher_request *areq)
 	}
 	writel(mode, ss->base + SS_CTL);
 
-	sg_miter_start(&mi, areq->src, sg_nents(areq->src),
-		       SG_MITER_FROM_SG | SG_MITER_ATOMIC);
-	sg_miter_start(&mo, areq->dst, sg_nents(areq->dst),
-		       SG_MITER_TO_SG | SG_MITER_ATOMIC);
-	sg_miter_next(&mi);
-	sg_miter_next(&mo);
-	if (!mi.addr || !mo.addr) {
-		dev_err_ratelimited(ss->dev, "ERROR: sg_miter return null\n");
-		err = -EINVAL;
-		goto release_ss;
-	}
 
 	ileft = areq->cryptlen / 4;
 	oleft = areq->cryptlen / 4;
 	oi = 0;
 	oo = 0;
 	do {
-		todo = min(rx_cnt, ileft);
-		todo = min_t(size_t, todo, (mi.length - oi) / 4);
-		if (todo) {
-			ileft -= todo;
-			writesl(ss->base + SS_RXFIFO, mi.addr + oi, todo);
-			oi += todo * 4;
-		}
-		if (oi == mi.length) {
-			sg_miter_next(&mi);
-			oi = 0;
+		if (ileft) {
+			sg_miter_start(&mi, areq->src, sg_nents(areq->src),
+					SG_MITER_FROM_SG | SG_MITER_ATOMIC);
+			if (toi)
+				sg_miter_skip(&mi, toi);
+			miter_err = sg_miter_next(&mi);
+			if (!miter_err || !mi.addr) {
+				dev_err_ratelimited(ss->dev, "ERROR: sg_miter return null\n");
+				err = -EINVAL;
+				goto release_ss;
+			}
+			todo = min(rx_cnt, ileft);
+			todo = min_t(size_t, todo, (mi.length - oi) / 4);
+			if (todo) {
+				ileft -= todo;
+				writesl(ss->base + SS_RXFIFO, mi.addr + oi, todo);
+				oi += todo * 4;
+			}
+			if (oi == mi.length) {
+				toi += mi.length;
+				oi = 0;
+			}
+			sg_miter_stop(&mi);
 		}
 
 		spaces = readl(ss->base + SS_FCSR);
 		rx_cnt = SS_RXFIFO_SPACES(spaces);
 		tx_cnt = SS_TXFIFO_SPACES(spaces);
 
+		sg_miter_start(&mo, areq->dst, sg_nents(areq->dst),
+			       SG_MITER_TO_SG | SG_MITER_ATOMIC);
+		if (too)
+			sg_miter_skip(&mo, too);
+		miter_err = sg_miter_next(&mo);
+		if (!miter_err || !mo.addr) {
+			dev_err_ratelimited(ss->dev, "ERROR: sg_miter return null\n");
+			err = -EINVAL;
+			goto release_ss;
+		}
 		todo = min(tx_cnt, oleft);
 		todo = min_t(size_t, todo, (mo.length - oo) / 4);
 		if (todo) {
@@ -112,9 +126,10 @@ static int noinline_for_stack sun4i_ss_opti_poll(struct skcipher_request *areq)
 			oo += todo * 4;
 		}
 		if (oo == mo.length) {
-			sg_miter_next(&mo);
 			oo = 0;
+			too += mo.length;
 		}
+		sg_miter_stop(&mo);
 	} while (oleft);
 
 	if (areq->iv) {
@@ -128,8 +143,6 @@ static int noinline_for_stack sun4i_ss_opti_poll(struct skcipher_request *areq)
 	}
 
 release_ss:
-	sg_miter_stop(&mo);
-	sg_miter_stop(&mi);
 	writel(0, ss->base + SS_CTL);
 	spin_unlock_irqrestore(&ss->slock, flags);
 	return err;
@@ -194,6 +207,8 @@ static int sun4i_ss_cipher_poll(struct skcipher_request *areq)
 	unsigned int obl = 0;	/* length of data in bufo */
 	unsigned long flags;
 	bool need_fallback = false;
+	unsigned long toi = 0, too = 0;
+	bool miter_err;
 
 	if (!areq->cryptlen)
 		return 0;
@@ -253,17 +268,6 @@ static int sun4i_ss_cipher_poll(struct skcipher_request *areq)
 	}
 	writel(mode, ss->base + SS_CTL);
 
-	sg_miter_start(&mi, areq->src, sg_nents(areq->src),
-		       SG_MITER_FROM_SG | SG_MITER_ATOMIC);
-	sg_miter_start(&mo, areq->dst, sg_nents(areq->dst),
-		       SG_MITER_TO_SG | SG_MITER_ATOMIC);
-	sg_miter_next(&mi);
-	sg_miter_next(&mo);
-	if (!mi.addr || !mo.addr) {
-		dev_err_ratelimited(ss->dev, "ERROR: sg_miter return null\n");
-		err = -EINVAL;
-		goto release_ss;
-	}
 	ileft = areq->cryptlen;
 	oleft = areq->cryptlen;
 	oi = 0;
@@ -271,6 +275,16 @@ static int sun4i_ss_cipher_poll(struct skcipher_request *areq)
 
 	while (oleft) {
 		if (ileft) {
+			sg_miter_start(&mi, areq->src, sg_nents(areq->src),
+				       SG_MITER_FROM_SG | SG_MITER_ATOMIC);
+			if (toi)
+				sg_miter_skip(&mi, toi);
+			miter_err = sg_miter_next(&mi);
+			if (!miter_err || !mi.addr) {
+				dev_err_ratelimited(ss->dev, "ERROR: sg_miter return null\n");
+				err = -EINVAL;
+				goto release_ss;
+			}
 			/*
 			 * todo is the number of consecutive 4byte word that we
 			 * can read from current SG
@@ -303,31 +317,38 @@ static int sun4i_ss_cipher_poll(struct skcipher_request *areq)
 				}
 			}
 			if (oi == mi.length) {
-				sg_miter_next(&mi);
+				toi += mi.length;
 				oi = 0;
 			}
+			sg_miter_stop(&mi);
 		}
 
 		spaces = readl(ss->base + SS_FCSR);
 		rx_cnt = SS_RXFIFO_SPACES(spaces);
 		tx_cnt = SS_TXFIFO_SPACES(spaces);
-		dev_dbg(ss->dev,
-			"%x %u/%zu %u/%u cnt=%u %u/%zu %u/%u cnt=%u %u\n",
-			mode,
-			oi, mi.length, ileft, areq->cryptlen, rx_cnt,
-			oo, mo.length, oleft, areq->cryptlen, tx_cnt, ob);
 
 		if (!tx_cnt)
 			continue;
+		sg_miter_start(&mo, areq->dst, sg_nents(areq->dst),
+			       SG_MITER_TO_SG | SG_MITER_ATOMIC);
+		if (too)
+			sg_miter_skip(&mo, too);
+		miter_err = sg_miter_next(&mo);
+		if (!miter_err || !mo.addr) {
+			dev_err_ratelimited(ss->dev, "ERROR: sg_miter return null\n");
+			err = -EINVAL;
+			goto release_ss;
+		}
 		/* todo in 4bytes word */
 		todo = min(tx_cnt, oleft / 4);
 		todo = min_t(size_t, todo, (mo.length - oo) / 4);
+
 		if (todo) {
 			readsl(ss->base + SS_TXFIFO, mo.addr + oo, todo);
 			oleft -= todo * 4;
 			oo += todo * 4;
 			if (oo == mo.length) {
-				sg_miter_next(&mo);
+				too += mo.length;
 				oo = 0;
 			}
 		} else {
@@ -352,12 +373,14 @@ static int sun4i_ss_cipher_poll(struct skcipher_request *areq)
 				obo += todo;
 				oo += todo;
 				if (oo == mo.length) {
+					too += mo.length;
 					sg_miter_next(&mo);
 					oo = 0;
 				}
 			} while (obo < obl);
 			/* bufo must be fully used here */
 		}
+		sg_miter_stop(&mo);
 	}
 	if (areq->iv) {
 		if (mode & SS_DECRYPTION) {
@@ -370,8 +393,6 @@ static int sun4i_ss_cipher_poll(struct skcipher_request *areq)
 	}
 
 release_ss:
-	sg_miter_stop(&mo);
-	sg_miter_stop(&mi);
 	writel(0, ss->base + SS_CTL);
 	spin_unlock_irqrestore(&ss->slock, flags);

Re: crypto: sun4i-ss: error with kmap

[Thomas Gleixner]

On Mon, Dec 07 2020 at 13:18, Corentin Labbe wrote:
> 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.

You can, but the ordering has to be correct and with sg_miter that's
probably hard to get right.

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

So the point is:

   sg_miter_next(&mi);  map 1 -> vaddr1
   sg_miter_next(&mo);  map 2 -> vaddr2

   do {
      ...
      if (cond) {
         sg_miter_next(&mi)
           sg_miter_stop()
             unmap(vaddr1);      unmaps map2   -> FAIL
             if (next_page)
                map();           maps map2 -> vaddr2 -> FAIL
      }

The only way how that could have ever worked is when the conditional
sg_miter_next(&mi) did not try to map a new page, i.e. end of data.

The ARM kunmap_atomic() had:

#ifdef CONFIG_DEBUG_HIGHMEM
		BUG_ON(vaddr != __fix_to_virt(idx));
		set_fixmap_pte(idx, __pte(0));
#else

which means the warning and clearing the PTE only happens when debugging
is enabled. That made your code "work" by chance because the unmap
leaves map2 intact which means the vaddr2 mapping stays valid, so the
access to it further down still worked.

   sg_miter_next(&mi);  map 1 -> vaddr1
   sg_miter_next(&mo);  map 2 -> vaddr2

   do {
      ...
      if (cond) {
         sg_miter_next(&mi)
           sg_miter_stop()
             unmap(vaddr1);      idx 2 ---> 1
                                 but mapping still valid for vaddr2
      }

   *vaddr2 = x;                  works by chance

But that also would cause trouble in the following case:

   sg_miter_next(&mi);  map 1 -> vaddr1
   sg_miter_next(&mo);  map 2 -> vaddr2

   do {
      ...
      if (cond) {
         sg_miter_next(&mi)
           sg_miter_stop()
             unmap(vaddr1);      idx 2 ---> 1
                                 but mapping still valid for vaddr2
      }

interrupt
   kmap_atomic(some_other_page)
     idx 1 -> 2                 map some_otherpage to vaddr2
   kunmap_atomic(vaddr2)        idx 2 --->  1
                                mapping still valid for vaddr2,
                                but now points to some_other_page
end of interrupt

      *vaddr2 = x;              <-- accesses some_other_page  -> FAIL

This is the worst one because it's random data corruption and extremly
hard to debug.

I made the warning and the pte clearing in the new code unconditional
just to catch any issues upfront which it did.

   sg_miter_next(&mi);  map 1 -> vaddr1
   sg_miter_next(&mo);  map 2 -> vaddr2

   do {
      ...
      if (cond) {
         sg_miter_next(&mi)
           sg_miter_stop()
             unmap(vaddr1);      unmaps map2   -> FAIL
             clear map2          invalidates vaddr2
      }

      *vaddr2 = x;              <-- accesses the unmapped vaddr2 -> CRASH
 
> 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.

That looks fine at least vs. the sg_miter/kmap_atomic usage.

Thanks,

        tglx