Ultimate Intervalometer - intermittent reboot faiure (powershot D10) - page 6 - Completed and Working Scripts

reyalp

14110

Re: Ultimate Intervalometer - intermittent reboot faiure (powershot D10)

« Reply #50 on: 20 / February / 2014, 01:59:22 »

Advertisements

Quote from: jules on 19 / February / 2014, 20:47:59

For the record:
Number of images on the card could be relevant (as CHDK experts have suggested in this and other discussions) but I cannot identify any particular numbers of images having an on influence the risk of reboot failure in my 'real world' use of ultimate intervalometer.

It's sensitive to timing. Number of files on the card will affect timing, but it isn't necessarily a simple relationship like more files == more likely to crash. It's not related to how much space is free.

Quote

I think this experiment indicates that memory use by a 'big' script is probably a factor in my intermittent reboot failures - as waterwingz suggested above.

I don't see any way that the size of the script would matter, except the file handle would be open for slightly longer.

Quote from: jules on 19 / February / 2014, 21:04:21

Another reboot failure occurred. Attached is the romlog.

reyalp, does this romlog contain the crucial info needed for you discover why reboot is failing....?

Unfortunately, it doesn't have much in the way of clues. The last ROM address in the stack dump is still in FsIoNotify code, so I can't see where in chdk it died.

00166FF0 is cfg_name which suggests that it could related to script parameters. I'll have to look at that code more to see if it makes sense, I think loading should be safe, but if it autosaves when the script starts that might be a problem.

Logged

Don't forget what the H stands for.

jules

73

Re: Ultimate Intervalometer - intermittent reboot faiure (powershot D10)

« Reply #51 on: 21 / February / 2014, 23:42:39 »

Thank you reyalp for the extra info. I'm sorry I cannot interpret the romlogs for myself. Really appreciate your time and patience with looking at them.

Sorry to say... I had another reboot failure (sigh!) and I've attached the new romlog.

Does this romlog perhaps have more useful clues than the last one?

ROMLOG_d10_reboot_fail_22feb2014.LOG (1.63 kB - downloaded 36 times.)

Logged

reyalp

14110

Re: Ultimate Intervalometer - intermittent reboot faiure (powershot D10)

« Reply #52 on: 22 / February / 2014, 00:40:37 »

Quote from: jules on 21 / February / 2014, 23:42:39

Does this romlog perhaps have more useful clues than the last one?

Unfortunately, it's pretty much identical to the other one.

I'll try to come up with another debug build for you this weekend.

Logged

Don't forget what the H stands for.

reyalp

14110

Re: Ultimate Intervalometer - intermittent reboot faiure (powershot D10)

« Reply #53 on: 22 / February / 2014, 18:37:03 »

Here's a new test build. The only thing it does different is log to the camera log (the text that appears in the romlog below the stack trace) for various file operations. This should allow me to see which part of the code caused the error.

Seeing that the stuff in your stack trace looked like it was related to the script params, I tried adding a param to my test script, but so far it hasn't crashed.

d10-100a-1.2.0-3354-full.zip (766.96 kB - downloaded 35 times.)

Logged

Don't forget what the H stands for.

reyalp

14110

Re: Ultimate Intervalometer - intermittent reboot faiure (powershot D10)

« Reply #54 on: 22 / February / 2014, 20:42:38 »

OK, it looks like this is connected to the "autostart once" setting. In my previous script testing, I was just setting autostart always in the menu and then running the script.

Attached version uses set_autostart(2) like ultimate.lua, and crashes with the same assert frequently.

Jules:
You could changing the line (318 in the current version of ultimate.lua)

Code: [Select]

    set_autostart(2)   -- autostart once

to

Code: [Select]

--    set_autostart(2)   -- autostart once

And then setting autostart to always in the script menu on your cameras.

I don't understand yet why this would be a problem, but I'd guess an extra file access is happening somewhere.

edit:
Since I can reproduce this myself now, I probably don't need more romlogs, but if it still crashes with autostart always, let me know.

edit:
Here's my romlog with file access logged to the camera log.

rbtest.lua (0.29 kB - downloaded 36 times.)

ROMLOG-AUTOSTART.LOG (3.32 kB - downloaded 37 times.)

« Last Edit: 22 / February / 2014, 20:48:02 by reyalp »

Logged

Don't forget what the H stands for.

reyalp

14110

Re: Ultimate Intervalometer - intermittent reboot faiure (powershot D10)

« Reply #55 on: 22 / February / 2014, 22:47:37 »

I made a log with UART redirection of a non-crashing start. I've also attached my debug logging code.

No crash

Code: [Select]

...
00000650: SS:_mkdir:A/CHDK/EDGE
00000660: SS:_Open(A/CHDK/DATA/RBTEST.cfg,0x301,0x1ff)
00000660: SS:_Open:4
00000680: SS:_Close:4
....

Crash

Code: [Select]

...
00000660: SS:_mkdir:A/CHDK/EDGE
00000670: SS:_Open(A/CHDK/CCHDK4.CFG,0x301,0x1ff)
00000670: SS:_Open:4
00000690: SS:_Close:4
00000740: SS:_Open(A/CHDK/DATA/RBTEST.cfg,0x301,0x1ff)

Since it doesn't get the the return of Open, it presumably crashed here. This matches the earlier stack trace evidence pointing toward the script CFG.

The obvious difference is the crash case saves CCHDK4.CFG to reset the autostart setting. However, this happens in the same task as the cfg save so it's not obvious to me why it should crash.

In the case of autostart, there really should be no need to save the script cfg, since the menu settings couldn't have been modified (as an aside, the cfg saving logic is buggy anyway, if you just go and edit the menu settings and don't run the script, it sometimes doesn't get saved)

edit:
The script cfg is saved when the CHDK cfg is saved, so skipping the save_params_values() in script_start_gui doesn't help.

RBUARTR.LOG (2.43 kB - downloaded 36 times.)

d10-autostart-crash-1.patch (2.79 kB - downloaded 39 times.)

« Last Edit: 23 / February / 2014, 00:22:18 by reyalp »

Logged

Don't forget what the H stands for.

jules

73

Re: Ultimate Intervalometer - intermittent reboot faiure (powershot D10)

« Reply #56 on: 23 / February / 2014, 18:34:27 »

Thank you very much reyalp for putting more time into this problem, great that you found issues related to autostart.

I've started another run with ultimate script, autostart line commented out, will let you know if it crashes. I'm still running 3338. I think build 3354 was for debugging that you've already done. Sorry if I misunderstood. Please tell me if I should run with 3354.

Maybe irrelevant at this point, but another odd thing:
After I download from card to laptop, and before starting a new run, I always delete the old ultimate log on the card. After the new run, ultimate.log has new text (matching new run) but file creation date-time matches the start of a prior run, although I'd expect the log file to be newly created when the script starts. Would it be normal for anything to do with prior log file to be saved in camera memory? Camera was off between runs, card removed and returned, CHDK autoboot from partition on card.

Many thanks again!

Logged

reyalp

14110

Re: Ultimate Intervalometer - intermittent reboot faiure (powershot D10)

« Reply #57 on: 23 / February / 2014, 18:44:04 »

Quote from: jules on 23 / February / 2014, 18:34:27

I've started another run with ultimate script, autostart line commented out, will let you know if it crashes. I'm still running 3338. I think build 3354 was for debugging that you've already done. Sorry if I misunderstood. Please tell me if I should run with 3354.

3354 will provide more useful information if you still get crashes. You don't need to go out of your way to change it, but if you have the opportunity you might as well.

Quote

After I download from card to laptop, and before starting a new run, I always delete the old ultimate log on the card. After the new run, ultimate.log has new text (matching new run) but file creation date-time matches the start of a prior run, although I'd expect the log file to be newly created when the script starts. Would it be normal for anything to do with prior log file to be saved in camera memory? Camera was off between runs, card removed and returned, CHDK autoboot from partition on card.

I really don't see how this could happen if you deleted the old file. There is certainly no way it could hang around in camera memory. There are cases when the timestamp doesn't get set on files, I don't remember the exact details, but I know they sometimes come up as 01/01/00 00:00:00. Maybe they can get recycled to random values in some cases too?

Logged

Don't forget what the H stands for.

reyalp

14110

Re: Ultimate Intervalometer - intermittent reboot faiure (powershot D10)

« Reply #58 on: 24 / February / 2014, 00:04:18 »

This is getting interesting. It appears the assert is not due to having too many open files, it's happening because the handle just opened is already in the FsIoNotify list.

In the attached patch, I made my own copy of the firmware Open function and the FsIoNotify function where the assert happens, modified to return an error code indicting how it would have reached the assert.

Making open fail allows the camera to boot, and the subsequent call to save_params_values succeeds.

I don't really understand how this can happen

d10-autostart-crash-3.patch (8.95 kB - downloaded 34 times.)

RBUARTR4.LOG (2.6 kB - downloaded 34 times.)

Logged

Don't forget what the H stands for.

philmoz

3450

Re: Ultimate Intervalometer - intermittent reboot faiure (powershot D10)

« Reply #59 on: 24 / February / 2014, 00:53:43 »

Quote from: reyalp on 24 / February / 2014, 00:04:18

This is getting interesting. It appears the assert is not due to having too many open files, it's happening because the handle just opened is already in the FsIoNotify list.

In the attached patch, I made my own copy of the firmware Open function and the FsIoNotify function where the assert happens, modified to return an error code indicting how it would have reached the assert.

Making open fail allows the camera to boot, and the subsequent call to save_params_values succeeds.

I don't really understand how this can happen

It happens when one task calls Close; but gets interrupted in the Close call, and another task then calls Open.

The call to Close, calls 'close' then later calls an FsNotify function to remove the closed file from the list.

When a task switch happens between these calls, the new task calls Open.
Open then calls 'open' and gets back the file handle from the previous call to 'close'.
Open then tries to call the FsNotify function to add the file handle to the list; but it is already there so it asserts.

This was what was discovered for the startup crash fix, and the fix was to call 'open' for files being read at startup instead of Open. In all likelihood switching to always using 'open' in CHDK (even for writing files) would probably work and eliminate more instances of the problem - we don't use whatever the FsNotify code is doing.

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)
g5x (1.00c, 1.01a, 1.01b)
g7x2 (1.01a, 1.01b, 1.10b)