new branch - CHDK : Elf Edition - Developers wanted - page 31 - General Discussion and Assistance

srsa_4c

3940

Re: new branch - CHDK : Elf Edition - Developers wanted

« Reply #300 on: 21 / February / 2015, 17:08:01 »

Advertisements

Quote from: philmoz on 21 / February / 2015, 16:45:10

Slightly different approach.
This is more generic, the rules for your modules are confined to the new makefile and can include other files if needed.

Thanks, that's much more elegant and more versatile. Please check it in if it's final.

Logged

Menu jumping/flickering on M10?

philmoz

3116

Re: new branch - CHDK : Elf Edition - Developers wanted

« Reply #301 on: 21 / February / 2015, 17:29:08 »

Quote from: srsa_4c on 21 / February / 2015, 17:08:01

Quote from: philmoz on 21 / February / 2015, 16:45:10
Slightly different approach.
This is more generic, the rules for your modules are confined to the new makefile and can include other files if needed.
Thanks, that's much more elegant and more versatile. Please check it in if it's final.

In revision 4031.

Phil.

Logged

CHDK ports:
sx30is (1.00c, 1.00h, 1.00l, 1.00n & 1.00p)
g12 (1.00c, 1.00e, 1.00f & 1.00g)
sx130is (1.01d & 1.01f)
ixus310hs (1.00a & 1.01a)
sx40hs (1.00d, 1.00g & 1.00i)
g1x (1.00e, 1.00f & 1.00g)

srsa_4c

3940

Re: new branch - CHDK : Elf Edition - Developers wanted

« Reply #302 on: 24 / September / 2015, 18:42:46 »

A note for those (including myself) who try to use a GUI module in their code:
When a module's init function is called, it will not block until the module is unloaded.
The init function will just return immediately and the caller's draw and keyboard callbacks will only be called again once the called module exits.
So, the following code is not suitable for enforcing limits on 'demo_var':

Code: [Select]

    libhexbox->hexbox_init( (int*)&demo_var, "Demo variable, enter 0-9", 0 );
    if (demo_var > 9)
        demo_var = 9;

Logged

Menu jumping/flickering on M10?

srsa_4c

3940

Re: new branch - CHDK : Elf Edition - Developers wanted

« Reply #303 on: 09 / June / 2019, 13:51:06 »

There is a problem somewhere in module related code.
Can be triggered by clicking on a text file from the file browser.
Three of my cameras (ixus110, a3200, a3400, all use exmem) tend to crash when doing what's written above. Enabling module logging makes the problem seemingly disappear (could not reproduce the crash with logging enabled).
On other cameras (ixus115, a490, both ARAM), the misbehaviour is that I get a clean screen with ALT mode active, and the keypress goes through to firmware (only on ixus115).

So far, I've only been able to reproduce these issues on cameras using SUBA (exmem or aram).
Don't know if related: https://chdk.setepontos.com/index.php?topic=13267

A typical exception on ixus110 (main.bin.dump attached):

Code: [Select]

Exception!! Vector 0x10
Occured Time  2009:03:18 04:28:17
Task ID: 13107228
Task name: PhySw
Exc Registers:
0x00000000
0x03CD5F7C
0xFFFFFFFF
0x03B98AFD
0x03CD3D34
0x03B9B1A8
0x03CD5F1C
0x03CD5F7C
0x19980218
0x19980218
0x19980218
0x19980218
0x000067A2
0x0030A980
0x03B8BEFF  -> LR, in gui_set_mode(), after the call to gui_set_need_restore()
0x03CD5AB4  -> PC, in allocated RAM
0x00000033
StackDump:
0x00000000
0x03BA6CD4
0x00000008
0x03BA6EAC
0x03BA6EAC
0x00000494
0x19980218
0x03B8C55D  -> in gui_kbd_process()
0x00000000
0x03BA7E6C
0x03BA6F00
0x03B8C825  -> in kbd_process()
0x03BA6CD4
0x19980218
0x19980218
0x03B8C875
0x00000000
0x19980218
0x19980218
0x03B9BFD0
0x00000000
0x03B9BF34
0x00000000
0x00000000
0x00989680
0x002F2E94
0x19980218
0x03B9BF58
0x19980218
0x19980218
0x00000800
0x00000000

main.bin.dump.7z (268.32 kB - downloaded 2 times.)

Logged

Menu jumping/flickering on M10?

reyalp

11994

Re: new branch - CHDK : Elf Edition - Developers wanted

« Reply #304 on: 09 / June / 2019, 17:41:29 »

I was able to reproduce this on sx160 (ARAM+exmem)

I tried a few times to trigger it on D10 (ARAM only, CHDK in ARAM) without success but the small amount of ARAM heap may mean the module stuff is happening in the system heap.

Not happening when module logging is annoying. Sending it to the camera log instead should be easy, I'll try that (I've actually wanted to have this an an option for a while, along with one to dump the module list in the exception handlers)

Logged

Don't forget what the H stands for.

reyalp

11994

Re: new branch - CHDK : Elf Edition - Developers wanted

« Reply #305 on: 09 / June / 2019, 21:42:35 »

Here's a quick and dirty patch to use the camera log. To do this properly, it should be value of conf.module_logging and the newlines should be handled better.

The output on sx160 looks like

Code: [Select]

00006530: SS:MOD     6530,LD,003a88bc,fselect.flt
00006570: UI:ScreenLock
00006570: UI:ScreenUnLock
00006590: UI:DisplayPhysicalScreenCBR
00008850: SS:MOD     8850,UN,        ,fselect.flt
00008850: SS:MOD     8850,LD,003a9fdc,txtread.flt

In the romlog

Code: [Select]

Exception!! Vector 0x10
Occured Time  2019:06:09 16:50:42
Task ID: 15794212
Task name: PhySw
Exc Registers:
0x00000000
0x003aa91c < R1 xx
0xffffffff
0x03cb6d5d < R3
0x003a8720
0x03cb9584 < R5
0x003aa8bc
0x003aa91c
0x19980218
0x19980218
0x19980218
0x19980218
0x00000003
0x003499b8
0x03caa2a3 < LR main.bin, ret from 3caa29e: f7ff ff69  bl 3caa174 <gui_set_need_restore>
0x003aa454 < PC - txtread.flt      3aa454: 5ce8       ldrb r0, [r5, r3] - in gui_read_draw
0x00000033
StackDump:
0x00000000
0x03cc4ca0 < kbd_new_state
0x00000004
0x03cc4e80
0x03cc4e80
0x00000494
0x19980218
0x03caa899 < end of gui_kbd_process
0x00000000
0x03cc5e28 < kbd_blocked
0x03cc4ed0 < last_kbd_key
0x03caab61 < return from gui_kbd_process in kbd_process

From loading the txtread.elf in ghidra, the faulting code

Code: [Select]

  3aa450: 4b42       ldr r3, [pc, #264] ; (3aa55c <gui_read_draw+0x2f0>)
  3aa452: 3348       adds r3, #72 ; 0x48
  3aa454: 5ce8       ldrb r0, [r5, r3]
  3aa456: 2820       cmp r0, #32

appears to be

Code: [Select]

for (; ii<n && buffer[ii]!=' ' && buffer[ii]!='\t' && buffer[ii]!='\r' && buffer[ii]!='\n'; ++ii) {

R3 + R5 is clearly bad, but it's not immediately obvious to me where the bad value comes from. The r3 value (3cb6d5d) is script_lang_id in the core as thumb. The r5 value is (3cb9584) is sprintf

This maybe suggests stack issues (context switch, regs clobbered?) or cache.

Other note:
I've noticed the camera sometimes crashes in a different way that doesn't generate a romlog. It seems to shutdown (or at least screen goes black) instantly rather than the slight delay that romlog crashes.

modules-cameralog-work-1.patch (2.49 kB - downloaded 2 times.)

Logged

Don't forget what the H stands for.

reyalp

11994

Re: new branch - CHDK : Elf Edition - Developers wanted

« Reply #306 on: 10 / June / 2019, 00:11:37 »

It looks like loading/unloading happen in different tasks. Something like
kbd_task in fselect triggers textread load
spytask module_tick_unloader unloads fselect

_module_load has a static 'lock' variable, but aside from probably not being strictly safe, it isn't used in unload at all.

I tried protecting _module_load and module_unload_idx with a semaphore (quick and dirty patch attached), and wasn't able to trigger the crash in >20 tries, where it usually happens within ~4. However, I haven't traced this carefully enough be sure this could cause the problem. It's also possible that there could be deadlocks: Modules trying to load/unload other modules in from their load/unload callbacks.

edit:
I tried camera logging the start/end of _module_load and module_unload idx. Crash case:

Code: [Select]

00016300: SS:_module_load start txtread.flt
00016300: SS:module_unload_idx start 1
00016300: SS:MOD    16300,UN,        ,fselect.flt
00016300: SS:module_unload_idx end 1
00016300: SS:MOD    16300,LD,003a9fdc,txtread.flt
00016300: SS:_module_load txtread.flt 2

If the order in the camera log is trusted, the fselect unload does happen between the start and end txtread load. However, they don't end up using the same index, which was my initial guess at how they could stomp on each other. (edit: numbers at the end are the indexes of the modules)

However libtxtread->read_file(selected_file) in gui_fselect presumably doesn't return until the filereader is completely loaded... after fselect is freed. If that memory were re-allocated in between, it would be Very Bad

It seems like, at a minimum, the running=0 currently done by exit_fselect should only be done at the very end of gui_fselect_kbd_process, and certainly after any additional modules are loaded. The rest of exit_fselect probably needs to happen before the new module start.

modules-sem-work-2.patch (4.15 kB - downloaded 3 times.)

« Last Edit: 10 / June / 2019, 01:36:46 by reyalp »

Logged

Don't forget what the H stands for.

philmoz

3116

Re: new branch - CHDK : Elf Edition - Developers wanted

« Reply #307 on: 10 / June / 2019, 05:21:22 »

The semaphore on the module code is probably a good idea and worth further investigation.

I think this issue is specific to the file browser / text reader interaction.

The file browser calls libtxtread->read_file with the address of a static buffer in the file browser module (selected_file).

From reyalp's log the file browser module is being unloaded while the text reader is loading (the file I/O is probably causing task switches).

If the memory for 'selected_file' in the file browser gets re-allocated and clobbered then the text reader will get a bad file name.

The attached quick fix patch allows a malloc'ed buffer to be passed to libtxtread->read_file which that function then frees.

My G12 exhibits the blank screen issue, while the G5X crashed - this patch appears to fix both.

Phil.

fselect_txtread_crash.patch (2.4 kB - downloaded 3 times.)

Logged

CHDK ports:
sx30is (1.00c, 1.00h, 1.00l, 1.00n & 1.00p)
g12 (1.00c, 1.00e, 1.00f & 1.00g)
sx130is (1.01d & 1.01f)
ixus310hs (1.00a & 1.01a)
sx40hs (1.00d, 1.00g & 1.00i)
g1x (1.00e, 1.00f & 1.00g)

reyalp

11994

Re: new branch - CHDK : Elf Edition - Developers wanted

« Reply #308 on: 10 / June / 2019, 13:15:38 »

Quote from: philmoz on 10 / June / 2019, 05:21:22

From reyalp's log the file browser module is being unloaded while the text reader is loading (the file I/O is probably causing task switches).

If the memory for 'selected_file' in the file browser gets re-allocated and clobbered then the text reader will get a bad file name.

Agreed, but I don't think this is the only problem. The memory allocated for the filebrowser code may also be freed before the kbd_task part of file browser finishes executing.

fselect.c gui_fselect_kbd_process, running in kbd_task

Code: [Select]

if (chk_ext(ext,"txt") || chk_ext(ext,"log") || chk_ext(ext,"csv"))
{
 exit_fselect(0); // sets running = 0, making module eligible to free in module_tick_unloader
 do_exit = 0;
 libtxtread->read_file(selected_file); // starts loading txtread, where IO may trigger task switch away from kbd task to spytask, which can run module_tick_unloader
}

So when libtxtread->read_file returns, the memory containing the executable code for fselect may have been freed and trashed.

IMO, the running=0 should happen at the very end of kbd_task processing, or have some kind of logic to set running=0 and return in the next iteration

edit:
The following case with module_run(selected_file) likely has similar problems. Running tetris from filebrowser crashed for me once in two tries on sx710. Probably even less used than the text reader case, but argues for a general solution.

« Last Edit: 10 / June / 2019, 23:57:55 by reyalp »

Logged

Don't forget what the H stands for.

philmoz

3116

Re: new branch - CHDK : Elf Edition - Developers wanted

« Reply #309 on: 11 / June / 2019, 04:42:58 »

Quote from: reyalp on 10 / June / 2019, 13:15:38

Quote from: philmoz on 10 / June / 2019, 05:21:22
From reyalp's log the file browser module is being unloaded while the text reader is loading (the file I/O is probably causing task switches).

If the memory for 'selected_file' in the file browser gets re-allocated and clobbered then the text reader will get a bad file name.
Agreed, but I don't think this is the only problem. The memory allocated for the filebrowser code may also be freed before the kbd_task part of file browser finishes executing.

Hmmm, that's a bit of a mess!

Here's an alternate patch that moves the call to before setting running = 0.

This also appears to fix both the G12 and G5X.

fselect_txtread_crash2.patch (1.9 kB - downloaded 4 times.)

Logged

CHDK ports:
sx30is (1.00c, 1.00h, 1.00l, 1.00n & 1.00p)
g12 (1.00c, 1.00e, 1.00f & 1.00g)
sx130is (1.01d & 1.01f)
ixus310hs (1.00a & 1.01a)
sx40hs (1.00d, 1.00g & 1.00i)
g1x (1.00e, 1.00f & 1.00g)