Re: crypto: hang in crypto_larval_lookup

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

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