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@xxxxxxxxxxxxxxxxxx> 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
