Re: crypto: hang in crypto_larval_lookup

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

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