Hi, expert
When I built test environment with hafnium v2.7 and optee 3.20.0, then execute xtest crypto cases repeatedly, several problems happened. Could you please give us some help?
debug log is as follows:
problem 1:
regression_40VERBOSE: hafnium func 0x84000073, vm->id 0x0, args->arg1 0x50, args->arg2 0x50, args->arg3 0x0, args->arg4 0x0
Current share states:
SHARE 0x0 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 0 retrieved, sender's original mode: 0x7
07_ecc Test TEE Internal API Generate ECC key
VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000000, args->arg4 0x0
E/TC:000 00 mobj_ffa_get_by_cookie:384 Populating mobj from rx buffer, cookie 0
VERBOSE: hafnium func 0x84000074, vm->id 0x8001, args->arg1 0x30, args->arg2 0x30, args->arg3 0x0, args->arg4 0x0
Current share states:
SHARE 0x0 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 0 retrieved, sender's original mode: 0x7
Current share states:
SHARE 0x0 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 1 retrieved, sender's original mode: 0x7
VERBOSE: hafnium func 0x84000065, vm->id 0x8001, args->arg1 0x0, args->arg2 0x0, args->arg3 0x0, args->arg4 0x0
D/TC:??? 00 tee_ta_init_pseudo_ta_session:296 Lookup pseudo TA cb3e5ba0-adf1-11e0-998b-0002a5d5c51b
D/TC:000 00 ldelf_load_ldelf:96 ldelf load address 0x40002000
D/LD: ldelf:134 Loading TS cb3e5ba0-adf1-11e0-998b-0002a5d5c51b
F/TC:??? 00 trace_syscall:190 syscall #3 (syscall_get_property)
F/TC:??? 00 trace_syscall:190 syscall #5 (syscall_open_ta_session)
D/TC:??? 00 ldelf_syscall_open_bin:142 Lookup user TA ELF cb3e5ba0-adf1-11e0-998b-0002a5d5c51b (Secure Storage TA)
VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1
VERBOSE: hafnium func 0x84000073, vm->id 0x0, args->arg1 0x50, args->arg2 0x50, args->arg3 0x0, args->arg4 0x0
Current share states:
SHARE 0x0 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 1 retrieved, sender's original mode: 0x7
SHARE 0x1 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 0 retrieved, sender's original mode: 0x7
VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0
E/TC:000 00 mobj_ffa_get_by_cookie:384 Populating mobj from rx buffer, cookie 0x1
VERBOSE: hafnium func 0x84000074, vm->id 0x8001, args->arg1 0x30, args->arg2 0x30, args->arg3 0x0, args->arg4 0x0
Current share states:
SHARE 0x0 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 1 retrieved, sender's original mode: 0x7
SHARE 0x1 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 0 retrieved, sender's original mode: 0x7
Current share states:
SHARE 0x0 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 1 retrieved, sender's original mode: 0x7
SHARE 0x1 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 1 retrieved, sender's original mode: 0x7
VERBOSE: hafnium func 0x84000065, vm->id 0x8001, args->arg1 0x0, args->arg2 0x0, args->arg3 0x0, args->arg4 0x0
VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1
VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0
VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1
VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0
VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1
VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0
VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1
VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0
I/TC: Cipher free ctx done!
I/TC: Performing software calc!
I/TC: Aead free ctx done!
VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1
VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0
I/TC: Performing software calc!
I/TC: Aead free ctx done!
VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1
VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0
I/TC: Performing software calc!
I/TC: Aead free ctx done!
VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1
VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0
I/TC: Performing software calc!
I/TC: Aead free ctx done!
VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1
VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0
VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1
VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0
VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1
VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0
VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1
VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0
I/TC: Cipher free ctx done!
I/TC: Performing software calc!
I/TC: Aead free ctx done!
VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1
VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0
VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1
VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0
D/TC:??? 00 ldelf_syscall_open_bin:146 res=0xffff0008
D/TC:??? 00 ldelf_syscall_open_bin:142 Lookup user TA ELF cb3e5ba0-adf1-11e0-998b-0002a5d5c51b (REE)
VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1
VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0
VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1
VERBOSE: hafnium func 0x84000073, vm->id 0x0, args->arg1 0x270, args->arg2 0x270, args->arg3 0x0, args->arg4 0x0
ERROR: arch_mm_pte_attrs error!
INFO: begin 0x7f3cf000 end 0x7f3d0000 level 0 pte 0x82084059e78 l_end 0x7f400000 entry_size 0x1000!
ERROR: mm_ptable_get_attrs_level second error!
INFO: begin 0x7f3ce000 end 0x7f3d0000 level 1 pte 0x82084052fc8 l_end 0x80000000 entry_size 0x200000!
ERROR: mm_ptable_get_attrs_level second error!
INFO: begin 0x7f3ce000 end 0x7f3d0000 level 2 pte 0x82084051008 l_end 0x8000000000 entry_size 0x40000000!
ERROR: mm_ptable_get_attrs_level second error!
INFO: begin 0x7f3ce000 end 0x7f3d0000 level 3 pte 0x82084035000 l_end 0x1000000000000 entry_size 0x8000000000!
ERROR: mm_ptable_get_attrs_level fail!
Current share states:
SHARE 0x0 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 1 retrieved, sender's original mode: 0x7
SHARE 0x1 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 1 retrieved, sender's original mode: 0x7
SHARE 0x2 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 0 retrieved, sender's original mode: 0x7
VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0
E/TC:000 00 mobj_ffa_get_by_cookie:384 Populating mobj from rx buffer, cookie 0x2
VERBOSE: hafnium func 0x84000074, vm->id 0x8001, args->arg1 0x30, args->arg2 0x30, args->arg3 0x0, args->arg4 0x0
Current share states:
SHARE 0x0 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 1 retrieved, sender's original mode: 0x7
SHARE 0x1 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 1 retrieved, sender's original mode: 0x7
SHARE 0x2 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 0 retrieved, sender's original mode: 0x7
Current share states:
SHARE 0x0 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 1 retrieved, sender's original mode: 0x7
SHARE 0x1 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 1 retrieved, sender's original mode: 0x7
SHARE 0x2 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 1 retrieved, sender's original mode: 0x7
VERBOSE: hafnium func 0x84000065, vm->id 0x8001, args->arg1 0x0, args->arg2 0x0, args->arg3 0x0, args->arg4 0x0
VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1
VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0
D/TC:??? 00 ldelf_syscall_open_bin:146 res=0
Problem2: VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1 VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0 VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1 VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0 VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1 VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0 VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1 VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0 I/TC: Cipher free ctx done! I/TC: Performing software calc! I/TC: Aead free ctx done! VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1 VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0 VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1 VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0 D/TC:??? 00 ldelf_syscall_open_bin:146 res=0xffff0008 D/TC:??? 00 ldelf_syscall_open_bin:142 Lookup user TA ELF cb3e5ba0-adf1-11e0-998b-0002a5d5c51b (REE) VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1 VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0 VERBOSE: hafnium func 0x84000070, vm->id 0x8001, args->arg1 0x80010000, args->arg2 0x0, args->arg3 0x0, args->arg4 0x1 VERBOSE: hafnium func 0x84000073, vm->id 0x0, args->arg1 0x270, args->arg2 0x270, args->arg3 0x0, args->arg4 0x0 Current share states: SHARE 0x0 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 1 retrieved, sender's original mode: 0x7 SHARE 0x1 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 1 retrieved, sender's original mode: 0x7 SHARE 0x2 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 0 retrieved, sender's original mode: 0x7 VERBOSE: hafnium func 0x8400006f, vm->id 0x0, args->arg1 0x8001, args->arg2 0x0, args->arg3 0x80000001, args->arg4 0x0 E/TC:000 00 mobj_ffa_get_by_cookie:384 Populating mobj from rx buffer, cookie 0x2 VERBOSE: hafnium func 0x84000074, vm->id 0x8001, args->arg1 0x30, args->arg2 0x30, args->arg3 0x0, args->arg4 0x0 Current share states: SHARE 0x0 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 1 retrieved, sender's original mode: 0x7 SHARE 0x1 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 1 retrieved, sender's original mode: 0x7 SHARE 0x2 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 0 retrieved, sender's original mode: 0x7 ERROR: Failed to allocate memory for page table VERBOSE: Insufficient memory to update recipient page table. Current share states: SHARE 0x0 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 1 retrieved, sender's original mode: 0x7 SHARE 0x1 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 1 retrieved, sender's original mode: 0x7 SHARE 0x2 (from VM 0x0, attributes 0x2f, flags 0x8, tag 0, to 1 recipients [VM 0x8001: 0x6 (offset 48)]): fully sent with 1 fragments, 0 retrieved, sender's original mode: 0x7 E/TC:000 00 spmc_retrieve_req:1418 Failed to fetch cookie 0x2 error code -3 E/TC:000 00 thread_spmc_populate_mobj_from_rx:1486 Failed to retrieve cookie from rx buffer 0x2 E/TC:??? 00 mobj_ffa_get_by_cookie:423 Failed to get cookie 0x2 internal_offs 0 D/TC:??? 00 thread_rpc_alloc:1261 mobj_ffa_get_by_cookie(0x2, 0): failed D/TC:??? 00 ldelf_syscall_open_bin:146 res=0xffff000c
Can anyone figure out what the problem is and give some debugging directions? Thanks! regards, wangyuan