Camera crash on startup - investigation.

Edit 27 Mar 2010
A fix for these startup crashes is now in the main CHDK code (changeset 1106).
To enable this fix add '#define CAM_STARTUP_CRASH_FILE_OPEN_FIX 1' to the relevant section of camera.h (see g12 or sx30 for example).
Edit: From changeset 1141 you need to add the #define to the 'platform_camera.h' file in your cameras platform directory.
Testing shows that this appears to fix the startup problem for the G12, SX30is, SX110is and IXUS1000 cameras.
========================================================

Recently there have been a number of postings related to various cameras intermittently crashing on startup. Usually the camera shutsdown shortly after starting CHDK. A romlog dump usually shows that the error is coming from the FsIoNotify code in the firmware.

Having experienced this with the G12 and SX30 ports I'm posting this discussion to outline what I've found while investigating the problem. I think I've found a solution for these cameras (fingers crossed) and hope this may help others.

Initially I thought it was related to the calls to 'taskHook' during CHDK startup and some changes I made appeared to fix the problem on the G12 and SX30 - unfortunately this was not the case and the problem re-occurred a few days ago.

After dumping the romlog and working back through the stack trace and the build dump file I tracked the problem down to a call to the firmware 'Open' function to open the symbol font file (in rbf_load_symbol). This is called during startup from conf_restore.

The firmware 'Open' function on the G12 and SX30 is shown below:
ROM:FF873BFC Open                                    ; CODE XREF: sub_FFB00988+20
ROM:FF873BFC                                         ; sub_FFB00B44+AC
ROM:FF873BFC                 STMFD   SP!, {R4-R8,LR}
ROM:FF873C00                 MOV     R5, R0
ROM:FF873C04                 LDRB    R0, [R0]
ROM:FF873C08                 MOV     R6, R2
ROM:FF873C0C                 MOV     R4, R1
ROM:FF873C10                 BL      _sub_FF875690__DriveLetterManager.c__103 ; LOCATION: DriveLetterManager.c:103
ROM:FF873C14                 MOV     R7, R0
ROM:FF873C18                 ORR     R4, R4, #0x20000
ROM:FF873C1C                 MOV     R1, #1
ROM:FF873C20                 BL      _sub_FF876A20__Mounter.c__0 ; LOCATION: Mounter.c:0
ROM:FF873C24                 MOV     R2, R6
ROM:FF873C28                 MOV     R1, R4
ROM:FF873C2C                 MOV     R0, R5
ROM:FF873C30                 BL      open                     <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
ROM:FF873C34                 MOV     R6, R0
ROM:FF873C38                 MOV     R2, R4
ROM:FF873C3C                 MOV     R1, R5
ROM:FF873C40                 BL      _sub_FF8735FC__FsIoNotify.c__0 ; LOCATION: FsIoNotify.c:0
ROM:FF873C44                 MOV     R0, R7
ROM:FF873C48                 BL      _sub_FF876A98__Mounter.c__0 ; LOCATION: Mounter.c:0
ROM:FF873C4C                 MOV     R0, R6
ROM:FF873C50                 LDMFD   SP!, {R4-R8,PC}
ROM:FF873C50 ; End of function Open

About two thirds of the way down this code is a call to 'BL open' - this is the IO library call to actually open the file. After this is another call to 'BL _sub_FF8735FC__FsIoNotify.c__0', and it's in this code that the actual crash is happening (via a call to DebugAssert).

The '_sub_FF8735FC__FsIoNotify.c__0' code takes the file handle returned from 'open' and attempts to store it into an array of data structures. At this stage I don't know exactly what the array is for; but it may be used to do buffered or asynchronous IO. The array only holds 10 entries and if the code can't find an empty slot it calls 'DebugAssert' which shuts down the camera.

What may be happening here is that there are already too many open files when the call to open the symbol font file is made, thus the camera shuts down. This could also explain why the problem is intermittent because the various startup tasks (both Canon and CHDK) will take different amounts of time depending on the card speed and what is on the card. So files will get opened and closed at different times.

In my case the G12 would crash more often if there were a lot of images or movies on the card when starting up, it would also crash more often on a partitioned 16GB card than it would on a single partition 4GB card.

Now if this array is used for some Canon buffered / asynch IO system then it's possible it isn't needed for CHDK. My idea is that it should be possible to use the 'open' function from CHDK instead of 'Open' (the one that 'Open' calls).

I've done this on the G12 and SX30 by changing the address of Open in the stubs_entry_2.s file and so far it does not seem to have caused any problems. CHDK on the cameras still seem to work ok and so far (touch wood) I have not had any more startup crashes.

Regards,
Phil.

Nice.

A while back I noticed that reading a file with "require" in Lua crashed the camera if it was recording video: http://chdk.setepontos.com/index.php?topic=5295.msg54076#msg54076

I never debugged it, but could be a similar problem I suppose (a570 is vxworks, though).

>I've done this on the G12 and SX30 by changing the address of Open in the stubs_entry_2.s file and so far >it does not seem to have caused any problems. CHDK on the cameras still seem to work ok and so far >(touch wood) I have not had any more startup crashes.

Do i understand correct, i need change the address of Open and Close to open and close ?

so old is

NHSTUB(Open, 0xFF837FF4)
NHSTUB(Close, 0xFF838060)
NHSTUB(close, 0xFF81AB8C)
NHSTUB(open, 0xFF81AADC)

new is then

NHSTUB(Open, 0xFF81AADC)
NHSTUB(Close, 0xFF81AB8C)
NHSTUB(close, 0xFF81AB8C)
NHSTUB(open, 0xFF81AADC)

Do i understand correct, i need change the address of Open and Close to open and close ?

I did not change 'Close', only 'Open'.

Both Open and Close appear to be wrappers around 'open' and 'close' that add and remove the file handle from an array (in the FsIoNotify code). Open crashes if there are no available slots in the array; but Close appears to do nothing if it can't find the file handle. My view is it's safer to continue to use Close in case you do have a file handle that was created using Open.

Phil.

Quote from: Bernd R on 06 / March / 2011, 14:01:36

Do i understand correct, i need change the address of Open and Close to open and close ?

I did not change 'Close', only 'Open'.

Both Open and Close appear to be wrappers around 'open' and 'close' that add and remove the file handle from an array (in the FsIoNotify code). Open crashes if there are no available slots in the array; but Close appears to do nothing if it can't find the file handle. My view is it's safer to continue to use Close in case you do have a file handle that was created using Open.

I would think that you always want to use the corresponding open/close functions. You should get a handle from the other "open" in CHDK if you replace it. If there are other functions that return a file descriptor that could be passed to "close" they need to be found and dealt with somehow.

Just because it's OK to use mismatched ones on your camera doesn't mean it's the same everywhere.

I would think that you always want to use the corresponding open/close functions. You should get a handle from the other "open" in CHDK if you replace it. If there are other functions that return a file descriptor that could be passed to "close" they need to be found and dealt with somehow.

Long term I agree 110%; but right now I haven't been through every line of code in CHDK to ensure that everything was matched up (for example are there any cases where CHDK calls yet another firmware function that allocates a file handle using Open?).

From looking at the firmware code for the G12 and SX30, passing an 'open' file handle to 'Close' has no side effects; but passing an 'Open' handle to 'close' will leave a stale entry in the FsIoNotify array - probably a bad thing.

Just because it's OK to use mismatched ones on your camera doesn't mean it's the same everywhere.

True.

The object of the thread was to document, and discuss, what I'd found on these cameras (related to the startup crashes), in the hope that it might help others experiencing similar problems.

Please don't take what I've posted earlier as a proven solution to all the reported startup problems - it's still a work in progress and may cause other problems not yet identified.

Phil.

I have now test short, and i notice the RAW crash i get always when first line is disable is gone.But it seem raw save time get slower.the crash without fix happen only on my sandisk card which store in 1.6 -1.8 sec a RAW.


//if (state_shooting_progress != SHOOTING_PROGRESS_PROCESSING)
{
        mkdir("A/DCIM");
        mkdir(dir);
}


My sandisk 12 megabyte /sec write speed need normaly 1.6 -1.8 sec savetime(chdk show when option is enable) for RAW, but when i use your fix, save time is 2.4 -2.6 sec.

my other 4 GB card that have write speed of 7 megabye /sec have with the fix too a save time of 2.4-2.6 sec.

On the 4 GB card your fix have no slowdown.

Do you notice time is same on your Camera ?
 
I test several times and only my sandisk 15 MB/sec , need more time.

the crash on series raw shoot happen on my camera only with RAW savetime of below 2 sec i think.

I have today order a sandisk 8gb 45 megabyte /sec (cost only 40 Eur with shipping), this should write speed  give of 35 megabyte.
when i have the card, i test speed here too, maybe on very fast cards speed loss is not so large, or its maybe larger.

I have hope your fix, fix my ptpcam mode 1 crash, that is too fsionotify problem.

But my camera crash with your FIX too

My sandisk 12 megabyte /sec write speed need normaly 1.6 -1.8 sec savetime(chdk show when option is enable) for RAW, but when i use your fix, save time is 2.4 -2.6 sec.

You're right, I had not initially noticed this; but the DNG save times are longer with this change.
This supports the theory that it is some method for buffered and/or asynchronous file IO.

Looks like a smarter solution may be needed - perhaps check for a free FsIoNotify slot and if one is available use Open, otherwise use open. I'll do some more investigation.

I have hope your fix, fix my ptpcam mode 1 crash, that is too fsionotify problem.

But my camera crash with your FIX too

I would not have thought the crashes are related (unless there is some file IO happening when you change modes). You need to look at the line number in the romlog file to see if it is the same error. Also look at the datestamp in the romlog - it's possible the mode change is not actually generating a new romlog and you are looking at one from a startup / raw save crash instead.

Edit: The crash in ptpcam mode call might happen if the addresses for PB2Rec, Rec2PB or set_control_event are wrong.


Phil.

Ok, here is another (more complex) solution. This involves modifying the open method in platform/generic/wrappers.c to check if there is an available slot in the FsIoNotify array and if there is call _Open otherwise call _open to avoid the assert crash.

This way the buffered/asynch IO will be used if possible; but it will fall back to standard IO if needed. You may still sometimes get slower RAW/DNG saves; but at least it shouldn't crash.

The change is to camera.h, wrappers.c and stubs_entry2.s

camera.h - add the following define to your camera section
#define FSIONOTIFY_FIX 1 // Do we need to check for an available FsIoNotify slot before calling Open?

wrappers.c - update the open code
int open (const char *name, int flags, int mode )
{
#ifdef CAM_DRYOS_2_3_R39
    if(name[0]!='A')return -1;
#endif
#ifdef FSIONOTIFY_FIX
extern int _FindFsIoNotifySlot(int);
if (_FindFsIoNotifySlot(-1) == 0) // Can't find space, FsIoNotify will assert and shutdown if we call Open, call open instead
return _open(name, flags, mode);
#endif
    return _Open(name, flags, mode);
}

stubs_entry_2.s - ensure you have the following three entries (note the addresses may vary for each camera)
NHSTUB(Open, 0xFF874500) // wrapper for 'open' to give buffered/asynch I/O ?
NHSTUB(FindFsIoNotifySlot, 0xFF874290) // Try and find an FsIoNotify array slot
NHSTUB(open, 0xFF81AADC) //

To find the FindFsIoNotifySlot code go to the Open code in the firmware dump and look for the subroutine call (BL) immediately following the 'BL open' call (it will be something like 'BL _sub_FF873F00__FsIoNotify.c__0'. Go to the code for this FsIoNotify routine and look for the memory address loaded into a register approx 1/3 way down. This is the array start address that is searched for an empty slot.

Search for occurrences of this array address in the firmware to find a function that searches the array for a given value - it may look some thing like the code below. This is the function I've called FindFsIoNotifySlot.
ROM:FF874290 sub_FF874290                            ; CODE XREF: sub_FF873F98+1C
ROM:FF874290                                         ; _sub_FF873FCC__FsIoNotify.c__540+1C
ROM:FF874290                 LDR     R2, =0x39578
ROM:FF874294                 MOV     R12, R0
ROM:FF874298                 MOV     R0, #0
ROM:FF87429C                 MOV     R1, #0
ROM:FF8742A0
ROM:FF8742A0 loc_FF8742A0                            ; CODE XREF: sub_FF874290+30
ROM:FF8742A0                 ADD     R3, R1, R1,LSL#1
ROM:FF8742A4                 LDR     R3, [R2,R3,LSL#5]
ROM:FF8742A8                 CMP     R3, R12
ROM:FF8742AC                 ADDEQ   R0, R1, R1,LSL#1
ROM:FF8742B0                 ADDEQ   R0, R2, R0,LSL#5
ROM:FF8742B4                 BXEQ    LR
ROM:FF8742B8                 ADD     R1, R1, #1
ROM:FF8742BC                 CMP     R1, #0xA
ROM:FF8742C0                 BLT     loc_FF8742A0
ROM:FF8742C4                 BX      LR
ROM:FF8742C4 ; End of function sub_FF874290

Regards,
Phil.

>This way the buffered/asynch IO will be used if possible; but it will fall back to standard IO if needed. You >may still sometimes get slower RAW/DNG saves; but at least it shouldn't crash.

this fix look ok, but i dont understand wy 10 open files are not enough for a camera.maybe you know how to print out the filenames of this open files, to see what files the camera have constant open ?

maybe chdk forget to close some files during init ?
the RAW save crash on my Ixus 1000 is trigger when use the mkdir command  mkdir("A/DCIM") in RAW save.

all is very strange, because i have add for test in the keyboard task a mkdir command, that is as often called as key check.

void my_kbd_read_keys() {
 mkdir("A/DCIM");

....

But when i have the sleep on boot and the code i write in raw.c no crash happen.

I get in mind, maybe a chdk task have too high priority.
normaly all tasks that use File IO should be lower in thread pri as the filesystem manager task

>Edit: The crash in ptpcam mode call might happen if the addresses for PB2Rec, Rec2PB or >set_control_event are wrong.

The addresses are correct, rudi tell in the ptp thread here what i should use as address, and the adress that are used are ok.

a crash with this function calls do not happen, when i disable the pys_status usb plugin bit, then the functions do not crash and work.

Its really strange that my Ixus 1000 seem only camera that do not work.

Edit:

I look again in old ptp post, and the error is not fsionotify.all the lots fsionotyfy i get i mis something.

ASSERT!! KerQueue.c Line 86
Occured Time  2011:01:30 10:01:55
Task ID: 16711713
Task name: CtrlSrv