Re: crypto: hang in crypto_larval_lookup

[Harald Freudenberger <freude@linux.vnet.ibm.com>]

On 02/24/2017 09:42 AM, Harald Freudenberger wrote:
> On 02/23/2017 05:02 PM, Harald Freudenberger wrote:
>> On 02/23/2017 12:39 PM, Herbert Xu wrote:
>>> On Thu, Feb 23, 2017 at 07:19:57PM +0800, Herbert Xu wrote:
>>>> Harald Freudenberger <freude@linux.vnet.ibm.com> wrote:
>>>>> Hello all
>>>>>
>>>>> I am currently following a hang at modprobe aes_s390 where
>>>>> crypto_register_alg() does not come back for the xts(aes) algorithm.
>>>>>
>>>>> The registration is waiting forever in algapi.c crypto_wait_for_test() but
>>>>> the completion never occurs. The cryptomgr is triggering a test via
>>>>> kthread_run to invoce cryptomgr_probe and this thread is calling the
>>>>> create() function of the xts template (file xts.c). Following this thread
>>>>> it comes down to api.c crypto_larval_lookup(name="aes") which is first
>>>>> requesting the module "crypto-aes" via request_module() successful and then
>>>>> blocking forever in requesting the module "crypto-aes-all".
>>>>>
>>>>> The xts(aes) has at registration CRYPTO_ALG_NEED_FALLBACK flag on.
>>>>>
>>>>> This problem is seen since about 6 weeks now, first only on the linux next
>>>>> kernel. Now it appers on the 4.10-rc kernels as well. And I still have no
>>>>> idea on how this could be fixed or what's wrong with just the xts
>>>>> registration (ecb, cbc, ctr work fine).
>>>>>
>>>>> Any ideas or hints?
>>>> Sorry, my fault.  I should've converted all the fallback users of
>>>> the old blkcipher interface over to skcipher before converting the
>>>> core algorithms to skcipher.
>>>>
>>>> I'll send a patch.
>>> Hmm, actually looks like I did convert this one :)
>>>
>>> Do you have ECB enabled in your configuration? XTS doesn't work
>>> without it.  Currently the Kconfig is missing a select on ECB so
>>> it could stop the generic XTS from loading.
>>>
>>> However, you seem to be stuck on straight AES which quite strange.
>>> The reason is that s390 crypto registers AES as the first thing so
>>> it should already be available.
>>>
>>> The fact that it hangs is expected because it's trying to find
>>> an acceptable AES implementation and in doing so it's loading
>>> s390-aes again.
>>>
>>> So we need to get to the bottom of why there is no acceptable
>>> "aes" registered.  Can you check /proc/crypto to see if the simple
>>> aes cipher is correctly registered (passing the selftest) after
>>> it hangs?
>>>
>>> You could also print out the type/mask in crypto_larval_lookup
>>> to see if perhaps the caller is asking for something unreasonable.
>>>
>>> Thanks,
>> Thanks for your help, here is cat /proc/crypto:
>> name         : xts(aes)
>> driver       :
>> module       : kernel
>> priority     : -1
>> refcnt       : 3
>> selftest     : passed
>> internal     : no
>> type         : larval
>> flags        : 0x415
>>
>> name         : xts(aes)
>> driver       : xts-aes-s390
>> module       : kernel
>> priority     : 400
>> refcnt       : 1
>> selftest     : passed
>> internal     : no
>> type         : larval
>> flags        : 0x514
>>
>> name         : xts(aes)
>> driver       : xts-aes-s390
>> module       : aes_s390
>> priority     : 400
>> refcnt       : 4
>> selftest     : unknown
>> internal     : no
>> type         : blkcipher
>> blocksize    : 16
>> min keysize  : 32
>> max keysize  : 64
>> ivsize       : 16
>> geniv        : <default>
>>
>> ...
>>
>> name         : ecb(aes)
>> driver       : ecb(aes-s390)
>> module       : kernel
>> priority     : 300
>> refcnt       : 1
>> selftest     : passed
>> internal     : no
>> type         : blkcipher
>> blocksize    : 16
>> min keysize  : 16
>> max keysize  : 32
>> ivsize       : 0
>> geniv        : <default>
>>
>> name         : ecb(aes)
>> driver       : ecb-aes-s390
>> module       : aes_s390
>> priority     : 400
>> refcnt       : 1
>> selftest     : passed
>> internal     : no
>> type         : blkcipher
>> blocksize    : 16
>> min keysize  : 16
>> max keysize  : 32
>> ivsize       : 0
>> geniv        : <default>
>>
>> name         : aes
>> driver       : aes-s390
>> module       : aes_s390
>> priority     : 300
>> refcnt       : 1
>> selftest     : passed
>> internal     : no
>> type         : cipher
>> blocksize    : 16
>> min keysize  : 16
>> max keysize  : 32
>> ...
>>
>> at the time where the modprobe hangs.
>>
>> And here is some syslog output (I added some printks for debugging) maybe
>> it may give you some hints about whats going on during the modprobe:
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_larval_lookup calling crypto_alg_lookup()
>> Feb 23 16:52:08 r35lp49 kernel: ->__crypto_alg_lookup(name=aes)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_get(alg.cra_name=aes) alg=0000000000f2dd68 alg.cra_refcnt=2
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_get(alg.cra_name=aes alg=0000000000f2dd68 alg.cra_driver_name=aes-generic alg.cra_module.name=(null))
>> Feb 23 16:52:08 r35lp49 kernel: <-__crypto_alg_lookup(name=aes) alg=0000000000f2dd68
>> Feb 23 16:52:08 r35lp49 kernel: <-crypto_larval_lookup(name=aes) alg=0000000000f2dd68
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_put(alg.cra_name=aes alg=0000000000f2dd68 alg.cra_driver_name=aes-generic, alg.cra_module.name=(null))
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_put(alg.cra_name=aes alg=0000000000f2dd68 alg.cra_refcnt=2)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_put(alg.cra_name=aes alg=000003ff80178480 alg.cra_driver_name=aes-s390, alg.cra_module.name=aes_s390)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_put(alg.cra_name=aes alg=000003ff80178480 alg.cra_refcnt=2)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_put(alg.cra_name=cbc(aes) alg=00000000b92d3548 alg.cra_driver_name=cbc(aes-s390), alg.cra_module.name=(null))
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_put(alg.cra_name=cbc(aes) alg=00000000b92d3548 alg.cra_refcnt=4)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_get(alg.cra_name=cbc(aes)) alg=00000000b92d3548 alg.cra_refcnt=4
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_get(alg.cra_name=cbc(aes) alg=00000000b92d3548 alg.cra_driver_name=cbc(aes-s390) alg.cra_module.name=(null))
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_put(alg.cra_name=cbc(aes) alg=00000000b92d4598 alg.cra_refcnt=1)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_put(alg.cra_name=cbc(aes) alg=00000000b92d3548 alg.cra_driver_name=cbc(aes-s390), alg.cra_module.name=(null))
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_put(alg.cra_name=cbc(aes) alg=00000000b92d3548 alg.cra_refcnt=4)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_put(alg.cra_name=cbc(aes) alg=00000000b92d3548 alg.cra_driver_name=cbc(aes-s390), alg.cra_module.name=(null))
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_put(alg.cra_name=cbc(aes) alg=00000000b92d3548 alg.cra_refcnt=3)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_put(alg.cra_name=cbc(aes) alg=00000000b92d3858 alg.cra_refcnt=3)
>> Feb 23 16:52:08 r35lp49 kernel: <-cryptomgr_probe(data=00000000b8b5d698)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_get(alg.cra_name=cbc(aes)) alg=00000000b92d3548 alg.cra_refcnt=3
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_get(alg.cra_name=cbc(aes) alg=00000000b92d3548 alg.cra_driver_name=cbc(aes-s390) alg.cra_module.name=(null))
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_put(alg.cra_name=cbc(aes) alg=00000000b92d3858 alg.cra_driver_name=, alg.cra_module.name=(null))
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_put(alg.cra_name=cbc(aes) alg=00000000b92d3858 alg.cra_refcnt=2)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_put(alg.cra_name=cbc(aes) alg=00000000b92d3858 alg.cra_refcnt=1)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_put(alg.cra_name=cbc(aes) alg=00000000b92d3548 alg.cra_driver_name=cbc(aes-s390), alg.cra_module.name=(null))
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_put(alg.cra_name=cbc(aes) alg=00000000b92d3548 alg.cra_refcnt=3)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_get(alg.cra_name=aes) alg=000003ff80178480 alg.cra_refcnt=2
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_get(alg.cra_name=aes alg=000003ff80178480 alg.cra_driver_name=aes-s390 alg.cra_module.name=aes_s390)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_mod_lookup(name=aes)
>> Feb 23 16:52:08 r35lp49 kernel: ->crypto_larval_lookup(name=aes)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_larval_lookup calling crypto_alg_lookup()
>> Feb 23 16:52:08 r35lp49 kernel: ->__crypto_alg_lookup(name=aes)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_get(alg.cra_name=aes) alg=0000000000f2dd68 alg.cra_refcnt=2
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_get(alg.cra_name=aes alg=0000000000f2dd68 alg.cra_driver_name=aes-generic alg.cra_module.name=(null))
>> Feb 23 16:52:08 r35lp49 kernel: <-__crypto_alg_lookup(name=aes) alg=0000000000f2dd68
>> Feb 23 16:52:08 r35lp49 kernel: <-crypto_larval_lookup(name=aes) alg=0000000000f2dd68
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_put(alg.cra_name=aes alg=0000000000f2dd68 alg.cra_driver_name=aes-generic, alg.cra_module.name=(null))
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_put(alg.cra_name=aes alg=0000000000f2dd68 alg.cra_refcnt=2)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_put(alg.cra_name=aes alg=000003ff80178480 alg.cra_driver_name=aes-s390, alg.cra_module.name=aes_s390)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_put(alg.cra_name=aes alg=000003ff80178480 alg.cra_refcnt=2)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_put(alg.cra_name=cbc(aes) alg=00000000b92d3548 alg.cra_driver_name=cbc(aes-s390), alg.cra_module.name=(null))
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_put(alg.cra_name=cbc(aes) alg=00000000b92d3548 alg.cra_refcnt=2)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_put(alg.cra_name=cbc(aes) alg=000003ff80178240 alg.cra_driver_name=cbc-aes-s390, alg.cra_module.name=aes_s390)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_put(alg.cra_name=cbc(aes) alg=000003ff80178240 alg.cra_refcnt=4)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_put(alg.cra_name=cbc(aes) alg=000003ff80178240 alg.cra_driver_name=cbc-aes-s390, alg.cra_module.name=aes_s390)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_put(alg.cra_name=cbc(aes) alg=000003ff80178240 alg.cra_refcnt=3)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_put(alg.cra_name=cbc(aes) alg=00000000b92d4248 alg.cra_refcnt=1)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_put(alg.cra_name=cbc(aes) alg=000003ff80178240 alg.cra_driver_name=cbc-aes-s390, alg.cra_module.name=aes_s390)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_put(alg.cra_name=cbc(aes) alg=000003ff80178240 alg.cra_refcnt=2)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_get(alg.cra_name=xts(aes)) alg=000003ff80178120 alg.cra_refcnt=2
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_get(alg.cra_name=xts(aes) alg=000003ff80178120 alg.cra_driver_name=xts-aes-s390 alg.cra_module.name=aes_s390)
>> Feb 23 16:52:08 r35lp49 kernel:   cryptomgr_notify(data=000003ff80178120)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_mod_lookup(name=xts-aes-s390)
>> Feb 23 16:52:08 r35lp49 kernel: ->crypto_larval_lookup(name=xts-aes-s390)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_larval_lookup calling crypto_alg_lookup()
>> Feb 23 16:52:08 r35lp49 kernel: ->__crypto_alg_lookup(name=xts-aes-s390)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_get(alg.cra_name=xts(aes)) alg=000003ff80178120 alg.cra_refcnt=3
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_get(alg.cra_name=xts(aes) alg=000003ff80178120 alg.cra_driver_name=xts-aes-s390 alg.cra_module.name=aes_s390)
>> Feb 23 16:52:08 r35lp49 kernel: <-__crypto_alg_lookup(name=xts-aes-s390) alg=000003ff80178120
>> Feb 23 16:52:08 r35lp49 kernel: <-crypto_larval_lookup(name=xts-aes-s390) alg=000003ff80178120
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_get(alg.cra_name=xts(aes)) alg=000003ff80178120 alg.cra_refcnt=4
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_mod_get(alg.cra_name=xts(aes) alg=000003ff80178120 alg.cra_driver_name=xts-aes-s390 alg.cra_module.name=aes_s390)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_mod_lookup(name=xts(aes))
>> Feb 23 16:52:08 r35lp49 kernel: ->crypto_larval_lookup(name=xts(aes))
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_larval_lookup calling crypto_alg_lookup()
>> Feb 23 16:52:08 r35lp49 kernel: ->__crypto_alg_lookup(name=xts(aes))
>> Feb 23 16:52:08 r35lp49 kernel: <-__crypto_alg_lookup(name=xts(aes)) alg=          (null)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_larval_lookup calling request_module(crypto-xts(aes))
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_larval_lookup calling crypto_alg_lookup(xts(aes))
>> Feb 23 16:52:08 r35lp49 kernel: ->__crypto_alg_lookup(name=xts(aes))
>> Feb 23 16:52:08 r35lp49 kernel: <-__crypto_alg_lookup(name=xts(aes)) alg=          (null)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_larval_lookup calling crypto_larval_add(xts(aes))
>> Feb 23 16:52:08 r35lp49 kernel: ->__crypto_alg_lookup(name=xts(aes))
>> Feb 23 16:52:08 r35lp49 kernel: <-__crypto_alg_lookup(name=xts(aes)) alg=          (null)
>> Feb 23 16:52:08 r35lp49 kernel: <-crypto_larval_lookup(name=xts(aes)) alg=00000000b92d48e8
>> Feb 23 16:52:08 r35lp49 kernel:   cryptomgr_notify(data=00000000b92d48e8)
>> Feb 23 16:52:08 r35lp49 kernel:   cryptomgr_schedule_probe(larval=00000000b92d48e8 larval.alg=00000000b92d48e8)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_get(alg.cra_name=xts(aes)) alg=00000000b92d48e8 alg.cra_refcnt=3
>> Feb 23 16:52:08 r35lp49 kernel: ->cryptomgr_probe(data=00000000b8b5d698 param.larval=00000000b92d48e8 param.larval.alg=00000000b92d48e8)
>> Feb 23 16:52:08 r35lp49 kernel: ->__crypto_lookup_template(xts)
>> Feb 23 16:52:08 r35lp49 kernel: <-__crypto_lookup_template() tmpl=0000000000f2dc00
>> Feb 23 16:52:08 r35lp49 kernel:   cryptomgr_probe(data=00000000b8b5d698) tmpl=0000000000f2dc00 tmpl.create=00000000006e00b8 err=-11
>> Feb 23 16:52:08 r35lp49 kernel: ->create(tmpl.name=xts)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_alg_mod_lookup(name=aes)
>> Feb 23 16:52:08 r35lp49 kernel: ->crypto_larval_lookup(name=aes)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_larval_lookup calling crypto_alg_lookup()
>> Feb 23 16:52:08 r35lp49 kernel: ->__crypto_alg_lookup(name=aes)
>> Feb 23 16:52:08 r35lp49 kernel: <-__crypto_alg_lookup(name=aes) alg=          (null)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_larval_lookup calling request_module(crypto-aes)
>> Feb 23 16:52:08 r35lp49 kernel:   crypto_larval_lookup calling request_module(crypto-aes-all)
>> --- modprobe aes_s390 hang ---
>>
>> regards H.Freudenberger
>>
> Here are the type and mask values:
>
> ...
> Feb 24 09:28:10 r35lp49 kernel: ->crypto_larval_lookup(name=aes,type=0x00000405,mask=0x0000248c)
> Feb 24 09:28:10 r35lp49 kernel:   crypto_larval_lookup calling crypto_alg_lookup(aes,0x00000405,0x0000248c)
> Feb 24 09:28:10 r35lp49 kernel: ->__crypto_alg_lookup(name=aes)
> Feb 24 09:28:10 r35lp49 kernel: <-__crypto_alg_lookup(name=aes) alg=          (null)
> Feb 24 09:28:10 r35lp49 kernel:   crypto_larval_lookup calling request_module(crypto-aes)
> Feb 24 09:28:10 r35lp49 kernel:   crypto_larval_lookup calling request_module(crypto-aes-all)
>
> type=0x00000405 = CRYPTO_ALG_TESTED, CRYPTO_ALG_TYPE_SKCIPHER
> mask=0x0000248c = CRYPTO_ALG_INTERNAL, CRYPTO_ALG_TESTED, CRYPTO_ALG_ASYNC, CRYPTO_ALG_TYPE_BLKCIPHER_MASK
>
I catched it: Thanks Herbert for your hint. The aes algorith registers with:
  .cra_flags = CRYPTO_ALG_TYPE_CIPHER |CRYPTO_ALG_NEED_FALLBACK
so later at __crypto_alg_lookup(aes, 0x0405, 0x248c)
this alg is not choosen because the check
  if ((q->cra_flags ^ type) & mask)
is true q->cra_flags = 0x0501 ^ 0x0405 & 0x248x => 0x0004

@Martin, I'll commit a patch asap.

Thanks for your help :-)

regards, H.Freudenberger