TA compilation with SPI driver

[deepakmnvl]

Hi, My task is to communicate with my SPI device through OP-TEE securely. For this , as a trial , I am extending hello_world program to included spi_init() and spi loopback test api. (copy spi_init() from optee_os to hello_world_ta.c)

I am getting many errors during TA compilation as it is not able to find headers, which are in optee_os folders. ( I have solved some by crude way of copying \optee_os\core\include\ folder to my TA folder but other errors appeared )

It would be very helpful if anybody can provide some documentation/usage/how-to tutorial of driver integration in OP-TEE ?

Thanks

[vchong]

Please double check everything from scratch. Your results are showing problems with both the board and your PC. Maybe disconnect everything else extra/unnecessary you have on the PC as well. Also check to see if it's maybe appearing as ttyUSB1 or 2 or etc.

[deepakmnvl]

problem found with both PCs I have checked till now :( :(

Got my board working now ...

[vchong]

So what was the problem with the PC that it exists on both? Please note so everyone can have a reference in the future.

[deepakmnvl]

I really dont know...

But one thing I noted is , even when I short jumpers 1-2 , auto start of hikey board is not happening. I need to manually press the button on the hikey board to start.

But , in the 3rd PC which worked for me now , auto start of hikey is fine .

[vchong]

Sorry. Testing buttons again.

[deepakmnvl]

hi, when I am Invoking static TA , from userTA , and sending a data through buffer, I am getting below error :

DEBUG:   [0x0] TEE-CORE:tee_ta_invoke_command:565:   => Error: ffff000f of 3
ERROR:   USER-TA: Panic 0xffff000f
ERROR:   TEE-CORE: TA panicked with code 0xffff000f usr_sp 0x400187b0 usr_lr 0x3f084d18
DEBUG:   [0x0] TEE-CORE:user_ta_enter:650: tee_user_ta_enter: TA panicked with code 0xffff000f
DEBUG:   [0x0] TEE-CORE:tee_ta_invoke_command:565:   => Error: ffff3024 of 3
DEBUG:   [0x0] TEE-CORE:tee_ta_invoke_command:541:    Panicked !
DEBUG:   [0x0] TEE-CORE:tee_ta_invoke_command:541:    Panicked !
DEBUG:   [0x0] TEE-CORE:tee_ta_close_session:318: tee_ta_close_session(0x3f05ff20)
DEBUG:   [0x0] TEE-CORE:tee_ta_close_session:337:    ... Destroy session
DEBUG:   [0x0] TEE-CORE:tee_ta_close_session:358:    ... Destroy TA ctx
DEBUG:   [0x0] TEE-CORE:tee_ta_close_session:318: tee_ta_close_session(0x3f05f4d0)

But , if I invoke the same TA without any parameters , it is fine.

My error seems to be :

define TEE_ERROR_SECURITY 0xFFFF000F

How to fix this security error ? Should I add my userTA name somewhere in staticTA ?

Thanks

[deepakmnvl]

The error occurred at:

function : tee_ta_verify_param()

```
switch (TEE_PARAM_TYPE_GET(param->types, n)) {
    case TEE_PARAM_TYPE_MEMREF_OUTPUT:
    case TEE_PARAM_TYPE_MEMREF_INOUT:
    case TEE_PARAM_TYPE_MEMREF_INPUT:

        if (param->param_attr[n] & TEE_MATTR_VIRTUAL) {
            p = virt_to_phys(
                param->params[n].memref.buffer);
            if (!p)
                            {            
                return TEE_ERROR_SECURITY;
                            }
        }

[deepakmnvl]

Can somebody clarify my query below ?

Is it possible to send memory reference in userTA to a staticTA like below ?

Code in userTA :

       unsigned char   pTxBuff[1] = { 0 }; 
        unsigned int size = 0; 
        pTxBuff[0] = 0xF0;
        size = sizeof(pTxBuff); 

        l_params[0].memref.buffer = pTxBuff;
        l_params[0].memref.size = size;
    res = TEE_InvokeTACommand(spi_test_session, 0, MY_TEST, l_pts, l_params, &origin);

Or should I use some shared memory concept to send/receive data between userTA and staticTA ?

[jforissier]

Hi @deepakmnvl ,

You are passing a reference to memory on the stack. Did you try using the heap instead? I.e., allocate pTxBuf using TEE_Malloc().

[deepakmnvl]

Hi @jforissier yes , I did tried that too... but the error is still there

below is the code with malloc :

        unsigned char*   pTxBuff = TEE_Malloc(1, 0) ;
        unsigned int size = 0; 

        pTxBuff[0] = 0xF0;
        size = sizeof(pTxBuff); 

        l_params[0].memref.buffer = pTxBuff;
        l_params[0].memref.size = size;

    res = TEE_InvokeTACommand(spi_test_session, 0, MY_TEST, l_pts, l_params, &origin);

Another thing is I am getting this error when parameter type is TEE_PARAM_TYPE_MEMREF_INOUT.

If its TEE_PARAM_TYPE_VALUE_INOUT, call is getting success , with all other code being same

[deepakmnvl]

I see that these commits are not there in my OPTEE OS stack. Does this matter ?

Also, Does heap data of a any specific userTA cannot be accessed by staticTA ?

[vchong]

I don't know the effects of those patches on SDP or what you're trying to do, but if you're using aosp+optee hikey build, then you're either on 2.3.0 or 2.4.0 which doesn't support SDP yet.

[deepakmnvl]

hi @vchong , I am just trying to pass a data buffer from userTA to staticTA, and I am getting "TA panicked" error as in the log given few posts above

I am still using your "hikey-n-4.9" repo, i think am having optee 2.3

Thanks

[jenswi-linaro]

If you're on optee 2.3 there's a bug/limitation preventing user TAs from calling a pseudo TA.

[deepakmnvl]

hmm.. I am able to call successfully when there are no parameters or even when params are TEE_PARAM_TYPE_VALUE_INOUT.

problem only when params are TEE_PARAM_TYPE_MEMREF_INOUT.

Anyways , if there's a bug , is there any other way - like shared memory ?

[jenswi-linaro]

The problem is with how addresses are translated when a pseudo TA is invoked. I don't think there's much to do about it than adding the fixes (or simply step up to 2.4).

[deepakmnvl]

ohh.. does 2.4 doesnt have this problem... means, I can allocate a heap in userTA and access correctly in staticTA without any issue ?

[jenswi-linaro]

Yes, if I remember correctly.

[deepakmnvl]

ok... hope it works I will check with this repo and let you guys know

Thanks

[deepakmnvl]

Hi , Now , the board is not booting.

adb logcat has continuous logs like below :

01-01 00:00:46.370  3009  3009 I RadioService: onFirstRef
01-01 00:00:46.371  3009  3009 E RadioService: couldn't load radio module radio.primary (No such file or directory)
01-01 00:00:46.372  3009  3009 E SoundTriggerHwService: couldn't load sound trigger module sound_trigger.primary (No such file or directory)
01-01 00:00:46.497  2952  2952 I mediaserver: ServiceManager: 0xf66193e0
01-01 00:00:46.518  2952  2952 W BatteryNotifier: batterystats service unavailable!
01-01 00:00:47.453  2947  2947 F appproc : Error creating cache dir /data/dalvik-cache/arm64 : Read-only file system
01-01 00:00:47.453  2947  2947 F libc    : Fatal signal 6 (SIGABRT), code -6 in tid 2947 (app_process64)
01-01 00:00:47.456  1788  1788 W         : debuggerd: handling request: pid=2947 uid=0 gid=0 tid=2947
01-01 00:00:47.466  3099  3099 E DEBUG   : debuggerd: failed to find a valid tombstone, default to using tombstone 0.
01-01 00:00:47.466  3099  3099 E DEBUG   : debuggerd: failed to open tombstone file '/data/tombstones/tombstone_00': Read-only file system
01-01 00:00:47.466  3099  3099 E         : debuggerd: failed to open tombstone file: Read-only file system
01-01 00:00:47.468  1788  1788 W         : debuggerd: resuming target 2947
01-01 00:00:47.605  1848  1848 I ServiceManager: service 'media.camera' died
01-01 00:00:47.606  1848  1848 I ServiceManager: service 'media.audio_flinger' died
01-01 00:00:47.606  1848  1848 I ServiceManager: service 'media.audio_policy' died
01-01 00:00:47.606  1848  1848 I ServiceManager: service 'media.radio' died
01-01 00:00:47.606  1848  1848 I ServiceManager: service 'media.sound_trigger_hw' died
01-01 00:00:47.606  1848  1848 I ServiceManager: service 'media.log' died
01-01 00:00:47.606  1848  1848 I ServiceManager: service 'media.player' died
01-01 00:00:47.606  1848  1848 I ServiceManager: service 'media.resource_manager' died

uart log is like below :

[   45.360602] init: Untracked pid 3180 killed by signal 9
[   45.528665] init: Service 'zygote_secondary' (pid 3116) killed by signal 6
[   45.535599] init: Service 'zygote_secondary' (pid 3116) killing any children in process group
[   47.548869] init: Starting service 'zygote'...
[   47.557683] init: Starting service 'zygote_secondary'...
[   47.568141] init: Starting service 'audioserver'...
[   47.577890] init: Starting service 'cameraserver'...
[   47.585967] init: Starting service 'installd'...
[   47.593460] init: Starting service 'media'...
[   47.599413] init: Starting service 'netd'...
[   47.637007] init: couldn't write 3280 to /dev/cpuset/camera-daemon/tasks: No such file or directory
[   47.665271] init: Service 'installd' (pid 3281) exited with status 1
[   47.671736] init: Service 'installd' (pid 3281) killing any children in process group
[   49.769406] init: Service 'zygote' (pid 3277) killed by signal 6
[   49.775469] init: Service 'zygote' (pid 3277) killing any children in process group
[   49.783353] init: write_file: Unable to open '/sys/android_power/request_state': No such file or directory
[   49.783431] init: write_file: Unable to write to '/sys/power/state': Invalid argument
[   49.783466] init: Service 'audioserver' is being killed...
[   49.783546] init: Service 'cameraserver' is being killed...
[   49.783612] init: Service 'media' is being killed...
[   49.783659] init: Service 'netd' is being killed...
[   49.787539] init: Service 'netd' (pid 3283) killed by signal 9
[   49.787558] init: Service 'netd' (pid 3283) killing any children in process group
[   49.788570] init: Service 'audioserver' (pid 3279) killed by signal 9
[   49.788586] init: Service 'audioserver' (pid 3279) killing any children in process group
[   49.789238] init: Service 'cameraserver' (pid 3280) killed by signal 9
[   49.789254] init: Service 'cameraserver' (pid 3280) killing any children in process group
[   49.789398] init: Untracked pid 3427 killed by signal 9
[   49.882787] init: Untracked pid 3338 killed by signal 9
[   49.886555] init: Service 'media' (pid 3282) killed by signal 9
[   49.886572] init: Service 'media' (pid 3282) killing any children in process group

Is there any issue with the stack ? or any other manual step I am missing ?

Thanks

[deepakmnvl]

In the meanwhile...

The problem is with how addresses are translated when a pseudo TA is invoked. I don't think there's much to do about it than adding the fixes (or simply step up to 2.4).

What are the fixes ? , or stepping to 2.4 means , can I take only OPTEE_OS folder from 2.4 repo ?

[vchong]

Lemme try this and get back to you.

[vchong]

I can reproduce and looking into this. In the meantime, please use following workaround:

Boot board into fastboot mode From pc, run fastboot format userdata and then fastboot reboot.

[deepakmnvl]

A quick question : An object is created in userTA using "TEE_CreatePersistentObject" APIs ,
Can we access this object in Secure TA ? If so , how ?

[deepakmnvl]

A little progress :

after formatting userdata, board booted OK. Now after restarting the board, I am getting adroid UI but homescreen is not coming.

uart log is stopping at :

[    8.095938] init: Starting service 'perfprofd'...
[    8.202754] Mali<2>: [    8.204896] Session 0x3B3A0000 with pid 1887 was granted higher priority.
[    8.347597] init: Starting service 'bootanim'...
[    8.497826] (stk) : timed out waiting for ldisc to be un-installed[    8.610961] (stk) :ldisc_install = 1
[    8.615665] uart-pl011 f7111000.uart: no DMA platform data
[    8.672099] (stc): st_tty_open [    8.675338] (stk) :line discipline installed
(stk) :ti-connectivity/TIInit_11.8.32.bts[    8.694028] (stk) :change remote baud rate command in firmware
(stk) :skipping the wait event of change remote baud[    8.723133] healthd: No battery devices found
[    8.727825] healthd: battery l=100 v=0 t=42.4 h=2 st=2 chg=a
[    9.485322] (stc): add_channel_to_table: id 4
[    9.489789] (stc): add_channel_to_table: id 2
[    9.494232] (stc): add_channel_to_table: id 3
[   10.549707] random: crng init done
[   11.537756] (stc): remove_channel_from_table: id 3
[   11.542668] (stc): remove_channel_from_table: id 2
[   11.547553] (stc): remove_channel_from_table: id 4
[   11.552433] (stc):  all chnl_ids unregistered [   11.556816] (stk) :ldisc_install = 0
(stc): st_tty_close [   16.345696] capability: warning: `main' uses 32-bit capabilities (legacy support in use)
[   23.658462] healthd: battery l=100 v=0 t=42.4 h=2 st=2 chg=a
[   24.212808] init: write_file: Unable to open '/proc/sys/vm/extra_free_kbytes': No such file or directory
[   25.490114] acc_open
[   25.493386] acc_release
[   29.117111] (hci_tty): inside hci_tty_open (ffffffc03a2802f8, ffffffc00ed8bc00)
[   29.133718] (stc):  chnl_id list empty :4 [   29.137750] (stk) : st_kim_start
(stk) :ldisc_install = 1[   29.472480] (stc): st_tty_open
(stk) :line discipline installed[   29.479152] (stk) :ti-connectivity/TIInit_11.8.32.bts
(stk) :change remote baud rate command in firmware[   29.501558] (stk) :skipping the wait event of change remote baud
[   31.745131] (stc): add_channel_to_table: id 4
[   31.749861] (stc): add_channel_to_table: id 2
[   31.755352] (stc): add_channel_to_table: id 3
[   34.059616] init: Service 'bootanim' (pid 1934) exited with status 0
[   34.314696] init: Starting service 'exec 3 (/system/bin/bootstat)'...

and any subsequent reboots have same issue.

If I format the userdata again , 1st reboot is fine. Subsequent reboots have issue again !!!

[deepakmnvl]

Hi , What is the hikey board version you guys are using , and whats RAM size in that ?

[vchong]

I only tested boot to prompt, not UI. Will need some time to check.

Board used was the Lemaker 8gb board.

[liuyq]

HI, deepakmnvl

I did not check the details about all the comments, and only talk about the the boot problem caused by userdata partition here, could you please help to check following 2 things:

1. run "fastboot format userdata", and what's the boot status for the first and second boot.
2. run "fastboot flash -S 256M userdata userdata.img", and how about the boot status for the first and second boot.

If any of the two could boot for the second time, and not able to show the UI correctly, please share both the output of command "dmesg" and "logcat -d"

Thanks, Yongqin Liu

[deepakmnvl]

Hi @liuyq , Regardign your queries ,

1 : in both the 1st and 2nd boots, UI didnt come-up.

logs are here : 1st boot dmesg 1st boot logcat 2nd boot dmesg 2nd boot logcat

2 : after flashing with attr -S 256M , board was down. Last few logs were :

[   46.001924] init: Service 'bootanim' (pid 1917) exited with status 0
[   46.417775] init: Starting service 'exec 3 (/system/bin/bootstat)'...
[   46.470939] init: Service 'exec 3 (/system/bin/bootstat)' (pid 2610) exited with status 0
[   46.479605] init: Starting service 'exec 4 (/system/bin/bootstat)'...
[   46.503528] init: Service 'exec 4 (/system/bin/bootstat)' (pid 2629) exited with status 0
[   46.512320] init: Starting service 'exec 5 (/system/bin/bootstat)'...
[   46.538155] init: Service 'exec 5 (/system/bin/bootstat)' (pid 2633) exited with status 0
[   46.546950] init: Starting service 'exec 6 (/system/bin/bootstat)'...
[   46.572352] init: Service 'exec 6 (/system/bin/bootstat)' (pid 2635) exited with status 0
[   47.240008] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.240020] binder: 2149:2149 transaction failed 29201, size 96-0
[   47.241013] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.241022] binder: 2149:2149 transaction failed 29201, size 96-0
[   47.254960] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.254969] binder: 2149:2149 transaction failed 29201, size 256-0
[   47.255647] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.255655] binder: 2149:2149 transaction failed 29201, size 256-0
[   47.256409] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.256417] binder: 2149:2149 transaction failed 29201, size 148-0
[   47.261683] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.261693] binder: 2149:2149 transaction failed 29201, size 96-0
[   47.262098] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.262106] binder: 2149:2149 transaction failed 29201, size 96-0
[   47.262409] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.262416] binder: 2149:2149 transaction failed 29201, size 96-0
[   47.262653] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.262660] binder: 2149:2149 transaction failed 29201, size 96-0
[   47.262878] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.262884] binder: 2149:2149 transaction failed 29201, size 96-0
[   47.322261] binder: undelivered transaction 13895
[   47.322437] binder: undelivered transaction 13917
[   47.322441] binder: undelivered transaction 13919
[   47.322446] binder: undelivered transaction 13920
[   47.322450] binder: undelivered transaction 13921
[   47.322454] binder: undelivered transaction 13922
[   47.322696] binder: undelivered transaction 13916
[   47.323315] binder: 1868:2563 transaction failed 29189, size 60-0
[   47.326714] binder: 2149:2211 transaction failed 29189, size 348-0
[   47.454017] binder: 2149:2164 transaction failed 29189, size 100-0
[   47.706972] binder: 2149:2149 transaction failed 29189, size 84-0
[   48.407877] binder: 2149:2758 transaction failed 29189, size 0-0

Then I gave "fastboot -w && fastboot continue" to get the board-up . Even in this boot , I got logs like

[   51.880027] binder: 2150:2162 transaction failed 29189, size 208-0
[   52.024609] binder: 2150:2150 transaction failed 29189, size 84-0

but , still I got shell.

@vchong , I asked about RAM size - is it 1GB or 2GB ?

[liuyq]

@deepakmnvl

From the following log from second dmesg log here https://pastebin.com/sXahf7vr:

[ 7.708755] EXT4-fs error (device mmcblk0p10): ext4_readdir:237: inode #525: block 1350106: comm init: path /data/nativetest: bad entry in directory: rec_len is smaller than minimal - offset=0(0), inode=0, rec_len=0, name_len=0 [ 7.732993] Aborting journal on device mmcblk0p10-8. [ 7.739389] EXT4-fs (mmcblk0p10): Remounting filesystem read-only [ 7.746913] EXT4-fs error (device mmcblk0p10): ext4_readdir:237: inode #536: block 1352389: comm init: path /data/nativetest64: bad entry in directory: rec_len is smaller than minimal - offset=0(0), inode=0, rec_len=0, name_len=0 [ 7.771519] EXT4-fs error (device mmcblk0p10): ext4_readdir:237: inode #547: block 1355269: comm init: path /data/piglit: bad entry in directory: rec_len is smaller than minimal - offset=0(0), inode=0, rec_len=0, name_len=0 [ 7.800488] init: SELinux: Could not set context for /data/misc/profiles/cur/0/foreign-dex: Read-only file system

it looks like the userdata partition is mounted as read-only. and it's probably caused by the userdata partition flashing.

Did you flash with " -S 256M" only for the userdata partition? like this: $ fastboot flash boot boot_fat.uefi.img or fastboot flash boot boot.img $ fastboot flash system system.img $ fastboot -S 256M flash userdata userdata.img

Thanks, Yongqin Liu

[deepakmnvl]

After flashing complete image normally , and took logs for #1 , then , I flashed only userdata with fastboot -S 256M flash userdata userdata.img and verified the behaviour

[liuyq]

@deepakmnvl and you still have the "EXT4-fs (mmcblk0p10): Remounting filesystem read-only" error in dmesg? could you share your boot.img, system.img and userdata.img so that I could try?

thought with following flash commands, it should be able to boot up successfully:

$ fastboot flash boot boot_fat.uefi.img or fastboot flash boot boot.img $ fastboot flash system system.img $ fastboot -S 256M flash userdata userdata.img

[deepakmnvl]

Boot was successful only after fastboot format userdata . Even then , my board halts sometimes. Final few logs are given in my previous comment.

Also, whats your hikey board RAM ? Mine's 1GB , and I suspect that might be causing these kinds of issues

[vchong]

Just to cover all bases, you did build with TARGET_USERDATAIMAGE_4GB=true option, right?

[deepakmnvl]

hi @vchong , mine's 8GB flash , 1GB RAM verison lemaker board

[vchong]

Oh ok. Haven't really heard of many 8gb/1gb boards out there. Usually 8/2 or 4/1. I'll see if I can try on my 4/1 board to see if there are any differences. Not sure what board @liuyq uses.

[liuyq]

what I am used is 8/2 version.

On 31 May 2017 at 22:08, vchong notifications@github.com wrote:

Oh ok. Haven't really heard of many 8gb/1gb boards out there. Usually 8/2 or 4/1. I'll see if I can try on my 4/1 board to see if there are any differences. Not sure what board @liuyq https://github.com/liuyq uses.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/OP-TEE/optee_os/issues/1461#issuecomment-305198006, or mute the thread https://github.com/notifications/unsubscribe-auth/ADK7DMCfQhgMUqzd4OkrscRvqPnO8fSSks5r_XRogaJpZM4Myz80 .

-- Best Regards, Yongqin Liu

mailing list

linaro-android@lists.linaro.org linaro-dev@lists.linaro.org http://lists.linaro.org/mailman/listinfo/linaro-android

[liuyq]

@deepakmnvl from the 2 dmesg log you provided, both of them show that the userdata partition is mounted as read-only, and this will make the android ui not displayed. with running "fastboot -S 256M flash userdata userdata.img", or running "fastboot flash userdata userdata.img" + "fastboot format userdata", the userdata partition should be mounted successfully(not read-only), could you please try to check if you could have the userdata partition mounted correctly?

or you could run device/linaro/hikey/installer/hikey/flash-all.sh in the recovery mode once, and then do following commands to check again. $ fastboot flash boot boot_fat.uefi.img or fastboot flash boot boot.img $ fastboot flash -w system system.img ##specify -w here and not run the fastboot flash for userdata paritition any more.

BTW, if possible, please share your images, so that we could try it with our local board as well.

[deepakmnvl]

hi @vchong , I need some quick answers here plss .

1 :

I am having problem where my function (func_b) is not returning to its parent caller(func_a). On UART0, last print in func_b appears. Then, I just get the shell. NW program which invokes this TA just hangs there and never exits (ctrl+c isnt working too)

To double check , I copied body of func_b into func_a , now , func_a doesnt return to its parent caller.

I am thinking stack got corrupted , or I dont have any clue !!! :( Anyways to debug it ?

2 :

My functions are compiled with Adr NDK r12b compiler.

What is the compiler OPTEE OS and its TAs are getting build ? For 64bit , this is used : prebuilts\gcc\linux-x86\aarch64\aarch64-linux-android-4.9 .. right ? And what are the compiler options ? Where are they defined ? I will use same to build my static libs too !!!

Regards

[deepakmnvl]

Hi @liuyq , After using "fastboot format userdata" , mounting was fine . But , many times(3 out of 5times), board just goes off Final logs are :

[   46.001924] init: Service 'bootanim' (pid 1917) exited with status 0
[   46.417775] init: Starting service 'exec 3 (/system/bin/bootstat)'...
[   46.470939] init: Service 'exec 3 (/system/bin/bootstat)' (pid 2610) exited with status 0
[   46.479605] init: Starting service 'exec 4 (/system/bin/bootstat)'...
[   46.503528] init: Service 'exec 4 (/system/bin/bootstat)' (pid 2629) exited with status 0
[   46.512320] init: Starting service 'exec 5 (/system/bin/bootstat)'...
[   46.538155] init: Service 'exec 5 (/system/bin/bootstat)' (pid 2633) exited with status 0
[   46.546950] init: Starting service 'exec 6 (/system/bin/bootstat)'...
[   46.572352] init: Service 'exec 6 (/system/bin/bootstat)' (pid 2635) exited with status 0
[   47.240008] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.240020] binder: 2149:2149 transaction failed 29201, size 96-0
[   47.241013] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.241022] binder: 2149:2149 transaction failed 29201, size 96-0
[   47.254960] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.254969] binder: 2149:2149 transaction failed 29201, size 256-0
[   47.255647] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.255655] binder: 2149:2149 transaction failed 29201, size 256-0
[   47.256409] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.256417] binder: 2149:2149 transaction failed 29201, size 148-0
[   47.261683] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.261693] binder: 2149:2149 transaction failed 29201, size 96-0
[   47.262098] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.262106] binder: 2149:2149 transaction failed 29201, size 96-0
[   47.262409] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.262416] binder: 2149:2149 transaction failed 29201, size 96-0
[   47.262653] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.262660] binder: 2149:2149 transaction failed 29201, size 96-0
[   47.262878] binder: 2274: binder_alloc_buf failed to map pages in userspace, no vma
[   47.262884] binder: 2149:2149 transaction failed 29201, size 96-0
[   47.322261] binder: undelivered transaction 13895
[   47.322437] binder: undelivered transaction 13917
[   47.322441] binder: undelivered transaction 13919
[   47.322446] binder: undelivered transaction 13920
[   47.322450] binder: undelivered transaction 13921
[   47.322454] binder: undelivered transaction 13922
[   47.322696] binder: undelivered transaction 13916
[   47.323315] binder: 1868:2563 transaction failed 29189, size 60-0
[   47.326714] binder: 2149:2211 transaction failed 29189, size 348-0
[   47.454017] binder: 2149:2164 transaction failed 29189, size 100-0
[   47.706972] binder: 2149:2149 transaction failed 29189, size 84-0
[   48.407877] binder: 2149:2758 transaction failed 29189, size 0-0

Sending my images, which are huge (~1GB) is difficult process. Can you try your images on 8/1 version boards, if you have any. If this is success, I will try to send my images to you !!!

Thanks

[vchong]

It's really hard to tell without knowing what func_b is actually doing, but sounds like it's not doing something right for sure. Maybe try increasing your log levels and see if more info appears. To do that, check your log levels in optee-packages.mk to see if they're already at 4. I think they are, but f not set them to 4. Also in device/linaro/hikey/bootloade/uefi-tools/platforms.config, under the [hikey] node, set BUILD_TOS=debug and uncomment TOS_BUILDFLAGS and set it to TOS_BUILDFLAGS=CFG_TEE_TA_LOG_LEVEL=4 DEBUG=1. Then delete out/dist/fip.bin, out/target/product/hikey/optee/arm-plat-hikey and optee/optee_os/out. Finally rebuild and reflash.

prebuilts\gcc\linux-x86\aarch64\aarch64-linux-android-4.9\bin sounds right. Why are your slashes backwards btw? Anyway, you can check the compiler used using which aarch64-linux-android-gcc. This has to be done after you source ./build/envsetup.sh though.

The compiler options/makefiles can be all over the place. It's not necessarily just a single location or file. You can maybe start from below and follow the trail: external/optee_test/Android.mk device/linaro/hikey/optee-packages.mk optee/optee_os/mk/aosp_optee.mk - there are many other *.mk files in optee_os too which can add options

I don't think we have any 8/1 boards for testing, but we don't think ram is the issue here anyway, at least not for the mounting as ro issue.

[liuyq]

@deepakmnvl sorry, I do not have 8/1 version board, and from the log you pasted, I do not see any log about going off. the binder message lines could be ignored here I think.

[deepakmnvl]

@vchong Many thx for ur quick replies @liuyq Will send my images, but how to send such large files ?

I compiled OPTEE with log level 4 , but I didnt see any specific log which can be suspected. I will inspect my code more .

Thanks

[deepakmnvl]

Hi , I need to read ~13KB of data from spi device , but always receiving 512bytes only !!! Is there any limitation in spi read/write data size ?

Also , present spi control driver seems to have some issue. When I tried to read around 40bytes of data , only recieved 39bytes. Logic analyzer shows 40bytes as received.

Then , I used previous version , and it was fine. Present working code of pl022_txrx8() function :

static enum spi_result pl022_txrx8(struct spi_chip *chip, uint8_t *wdat,
    uint8_t *rdat, size_t num_pkts)
{
    size_t i = 0;
    size_t j = 0;
    struct pl022_data *pd = container_of(chip, struct pl022_data, chip);
        size_t num_rxpkts = num_pkts ;

    if (pd->data_size_bits != 8) {
        EMSG("data_size_bits should be 8, not %u",
            pd->data_size_bits);
        return SPI_ERR_CFG;
    }

    while (i < num_pkts) {
        if (read8(pd->base + SSPSR) & SSPSR_TNF)
            /* tx 1 packet */
            write8(wdat[i++], pd->base + SSPDR);
    }

    do {
        while ((read8(pd->base + SSPSR) & SSPSR_RNE) &&
            (j < num_rxpkts))
            /* rx 1 packet */
            rdat[j++] = read8(pd->base + SSPDR);
    } while ((read8(pd->base + SSPSR) & SSPSR_BSY) && (j < num_rxpkts));
    /* Capture remaining rdat not read above */
    if (j != num_pkts)
        {
            EMSG("Packets requested %zu, received %zu",num_rxpkts, j);
            return SPI_ERR_PKTCNT;
        }

    return SPI_OK;
}

[deepakmnvl]

Hi , I changed spi function as below , and I am able to read full data (13KB) without any missing byte

static enum spi_result pl022_txrx8(struct spi_chip *chip, uint8_t *wdat, uint8_t *rdat, size_t num_pkts)
{
    size_t i = 0;
    size_t j = 0;
    struct pl022_data *pd = container_of(chip, struct pl022_data, chip);
        size_t num_rxpkts = num_pkts ;

    if (pd->data_size_bits != 8) {
        EMSG("data_size_bits should be 8, not %u",
            pd->data_size_bits);
        return SPI_ERR_CFG;
    }

    while (i < num_pkts) {
        if (read8(pd->base + SSPSR) & SSPSR_TNF)
            /* tx 1 packet */
            write8(wdat[i++], pd->base + SSPDR);

                if (rdat)
                    if (read8(pd->base + SSPSR) & SSPSR_RNE) {
                        /* rx 1 packet */
                        rdat[j++] = read8(pd->base + SSPDR);
                    }
        }

    do {
        while ((read8(pd->base + SSPSR) & SSPSR_RNE) &&
            (j < num_rxpkts))
            /* rx 1 packet */
            rdat[j++] = read8(pd->base + SSPDR);
    } while ((read8(pd->base + SSPSR) & SSPSR_BSY) && (j < num_rxpkts));

       EMSG("Packets requested %zu, received %zu \n",num_rxpkts, j);

    if (j != num_pkts)
        {
            return SPI_ERR_PKTCNT;
        }

    return SPI_OK;
}

Thanks

[deepakmnvl]

Hi , I am getting TA panic when I am calling a function from one of my attached static lib :

DEBUG:   [0x0] TEE-CORE:abort_handler:555: [abort] abort in User mode (TA will panic)
ERROR:   TEE-CORE:
ERROR:   TEE-CORE: user TA data-abort at address 0x38 (translation fault)
ERROR:   TEE-CORE:  esr 0x92000046  ttbr0 0x100003f09d020   ttbr1 0x00000000   cidr 0x0
ERROR:   TEE-CORE:  cpu #1          cpsr 0x60000100
ERROR:   TEE-CORE: x0  0000000000000007 x1  0000000000000038
ERROR:   TEE-CORE: x2  0000000000000070 x3  0000000040d78158
ERROR:   TEE-CORE: x4  00000000405ffe30 x5  0000000000000001
ERROR:   TEE-CORE: x6  0000000000000038 x7  0000000000000070
ERROR:   TEE-CORE: x8  0000000000000001 x9  000000003f0a90c0
ERROR:   TEE-CORE: x10 00000000000000aa x11 00000000000045c7
ERROR:   TEE-CORE: x12 0000000000004c66 x13 00000000406007b0
ERROR:   TEE-CORE: x14 0000000000000000 x15 0000000000000000
ERROR:   TEE-CORE: x16 000000003f01f4e4 x17 0000000000000000
ERROR:   TEE-CORE: x18 0000000000000000 x19 000000003f0a91b0
ERROR:   TEE-CORE: x20 0000000000000000 x21 000000003f06bad0
ERROR:   TEE-CORE: x22 00000000000005f0 x23 0000000000000000
ERROR:   TEE-CORE: x24 0000000000000000 x25 0000000000000000
ERROR:   TEE-CORE: x26 0000000000000000 x27 0000000000000000
ERROR:   TEE-CORE: x28 0000000000000000 x29 0000000040600420
ERROR:   TEE-CORE: x30 0000000040627df8 elr 000000004063bf60
ERROR:   TEE-CORE: sp_el0 0000000040600420
ERROR:   TEE-CORE: Status of TA ec72de37-4c66-45c7-aa6a-5c6a8cfbc089 (0x3f07fcf0) (active)
ERROR:   TEE-CORE: - load addr : 0x40601000    ctx-idr: 1
ERROR:   TEE-CORE: - stack: 0x40000000 6293504
ERROR:   TEE-CORE: sect 0 : va 0x40000000 pa 0x3f9a8000 0x601000
ERROR:   TEE-CORE: sect 1 : va 0x40601000 pa 0x3f200000 0x6f000
ERROR:   TEE-CORE: sect 2 : va 0x40670000 pa 0x3f26f000 0x25000
ERROR:   TEE-CORE: sect 3 : va 0x40695000 pa 0x3f294000 0x714000
ERROR:   TEE-CORE: sect 4 : va 0x40e00000 pa 0x3ee01000 0x2000
ERROR:   TEE-CORE: sect 5 : va 0 pa 0 0
ERROR:   TEE-CORE: sect 6 : va 0 pa 0 0
ERROR:   TEE-CORE: sect 7 : va 0 pa 0 0
DEBUG:   [0x0] TEE-CORE:user_ta_enter:590: tee_user_ta_enter: TA panicked with code 0xdeadbeef
DEBUG:   [0x0] TEE-CORE:tee_ta_invoke_command:613:  => here  ffff3024
DEBUG:   [0x0] TEE-CORE:tee_ta_invoke_command:622:   => Error: ffff3024 of 3
DEBUG:   [0x0] TEE-CORE:tee_ta_invoke_command:604:    Panicked !

Any pointers to check this issue would be of great help. Thanks

[jforissier]

Hi @deepakmnvl,

Your TA is causing a data abort, i.e., accessing an invalid address. Luckily, you can get more information on the location of the invalid access thanks to patches I have merged recently: 31a2964 ("core: dump call stack of user TAs on abort"), as well as 733a15f ("scripts: add symbolize.py").

To benefit from this "stack dump" feature, just make sure you have the above commits in your optee_os history (you may want to rebase your repo on top of the current master branch), and build with CFG_TEE_CORE_DEBUG=y. Then run your test case again. When the TA aborts, its call stack will be dumped to the console as a list of addresses. You can then paste the whole dump through scripts/symbolize.py and you should obtain function names, source files and line numbers (see symbolize.py -h for usage information).

[deepakmnvl]

Hi @jforissier , Got the dump , but couldnt get symbolize.py running When I paste my call stack in symbolize.py , nothing happens. Then press ^d, same addresses gets print again , thats it !!!

Anyways , my crash is as below :

DEBUG: [0x0] TEE-CORE:abort_handler:684: [abort] abort in User mode (TA will panic) ERROR: TEE-CORE: ERROR: TEE-CORE: user TA data-abort at address 0x40d871c6 (alignment fault) ERROR: TEE-CORE: esr 0x92000061 ttbr0 0x100003f09d000 ttbr1 0x00000000 cidr 0x0 ERROR: TEE-CORE: cpu #0 cpsr 0x20000100 ERROR: TEE-CORE: x0 0000000040d871c6 x1 0000000000000000 ERROR: TEE-CORE: x2 0000000000000006 x3 0000000000000001 ERROR: TEE-CORE: x4 0000000000000004 x5 0000000000000000 ERROR: TEE-CORE: x6 0000000040d871c6 x7 0000000000000070 ERROR: TEE-CORE: x8 0000000000000001 x9 000000003f0a90c0 ERROR: TEE-CORE: x10 00000000000000aa x11 00000000000045c7 ERROR: TEE-CORE: x12 0000000000004c66 x13 00000000406007b0 ERROR: TEE-CORE: x14 0000000000000000 x15 0000000000000000 ERROR: TEE-CORE: x16 000000003f0201c8 x17 0000000000000000 ERROR: TEE-CORE: x18 0000000000000000 x19 0000000040d87178 ERROR: TEE-CORE: x20 0000000040d871a0 x21 00000000406a4000 ERROR: TEE-CORE: x22 0000000000000007 x23 000000000000000d ERROR: TEE-CORE: x24 0000000000000bb8 x25 0000000000000800 ERROR: TEE-CORE: x26 000000000000ffff x27 0000000000000038 ERROR: TEE-CORE: x28 0000000000000000 x29 00000000406003d0 ERROR: TEE-CORE: x30 000000004064164c elr 0000000040642714 ERROR: TEE-CORE: sp_el0 00000000406003d0 ERROR: TEE-CORE: Status of TA ec72de37-4c66-45c7-aa6a-5c6a8cfbc089 (0x3f07f150) (active) ERROR: TEE-CORE: - load addr : 0x40601000 ctx-idr: 1 ERROR: TEE-CORE: - stack: 0x40000000 6293504 ERROR: TEE-CORE: sect 0 : va 0x40000000 pa 0x3f9b7000 0x601000 ERROR: TEE-CORE: sect 1 : va 0x40601000 pa 0x3f200000 0x7d000 ERROR: TEE-CORE: sect 2 : va 0x4067e000 pa 0x3f27d000 0x26000 ERROR: TEE-CORE: sect 3 : va 0x406a4000 pa 0x3f2a3000 0x714000 ERROR: TEE-CORE: sect 4 : va 0x40e00000 pa 0x3ee01000 0x2000 ERROR: TEE-CORE: sect 5 : va 0 pa 0 0 ERROR: TEE-CORE: sect 6 : va 0 pa 0 0 ERROR: TEE-CORE: sect 7 : va 0 pa 0 0 ERROR: TEE-CORE: Call stack: ERROR: TEE-CORE: pc 0x0000000040642714 ERROR: TEE-CORE: pc 0x000000004062d204 ERROR: TEE-CORE: pc 0x0000000040621eb4 ERROR: TEE-CORE: pc 0x0000000040621924 ERROR: TEE-CORE: pc 0x0000000040620bfc ERROR: TEE-CORE: pc 0x0000000040612398 ERROR: TEE-CORE: pc 0x0000000040609468 ERROR: TEE-CORE: pc 0x0000000040607858 ERROR: TEE-CORE: pc 0x00000000406075dc ERROR: TEE-CORE: pc 0x000000004066de58 ERROR: TEE-CORE: pc 0x000000004066dee4 ERROR: TEE-CORE: pc 0x000000003f00b12c DEBUG: [0x0] TEE-CORE:user_ta_enter:597: tee_user_ta_enter: TA panicked with code 0xdeadbeef DEBUG: [0x0] TEE-CORE:tee_ta_invoke_command:613: => here ffff3024 DEBUG: [0x0] TEE-CORE:tee_ta_invoke_command:622: => Error: ffff3024 of 3 DEBUG: [0x0] TEE-CORE:tee_ta_invoke_command:604: Panicked !

Using aarch64-linux-android-addr2line , I get only proper value for 0x000000003f00b12c which is "optee/optee_os/core/arch/arm/kernel/thread.c:1108" in "tee.elf"

Remaining address gives "?"

I think 40* series addresses are virtual ones ?? I am having no clue about (alignment fault)** kind of issues. Any help regarding this would be huge help

Thanks

[jforissier]

Hi @deepakmnvl,

It looks like you need to cherry-pick more commits, sorry for not mentioning them:

7bbee6e ("core: show user TA architecture on abort") 1bc08be ("core: cosmetic updates to the abort dumps for better consistency")

They are required because the symbolize.py script expects a specific format, which was slightly changed by the above commits. Please add them to your optee_os and the script should work.

It's not easy to use addr2line by hand because you have to subtract the load address of the TA.

Finally, note that the last address in the stack is indeed inside tee.elf, and should normally not be printed as part of the TA call stack (let's call this a minor bug in the user TA stack unwinding code ;-)).

[jforissier]

One more thing: assuming I have decoded esr correctly, it's a write access, unspecified size. Since the address is 0x40d871c6, which can be divided by 2 but not 4 or 8, it must be a 32- or 64-bit write. It should become obvious once you know the line in the source code (hopefully!).