sudden shutdown when it's dark. - General Help and Assistance on using CHDK stable releases - CHDK Forum
« previous next »
Pages: [1] 2   Go Down

sudden shutdown when it's dark.

  • 10 Replies
  • 1076 Views
*

Offline Mlapse

  • *****
  • 583
  • S95 S110
sudden shutdown when it's dark.
« on: 14 / January / 2024, 03:56:08 »
Advertisements
I have 2x S110 in use, one is 102B the other 103A.
They both run build:1.6.1-6200 and my script that shoots at a set interval.
Canon settings are identical.
 
Now, this is my second 102B that occasionally shuts down.
This always happens in the evening/early night, never in the morning or daytime.
It can go for weeks without this flaw or it can happen each week.
I've changed power supply, reformatted sd cards, but it keeps happening every now and then with the 102B
But usually i forget to make a romlog when this happens.

I've got one now and another in a few weeks, that one is still in the cam.
the shutdown happened at 17:14, the cam by then had an exposure of 4 seconds because it was already dark.

I do not understand what motion detect has to do with anything in my setup since i don't use it.

Does anybody have a clear idea of what is going on?
Logged
frustration is a key ingredient in progress
*

Offline reyalp

  • ******
  • 14080
Re: sudden shutdown when it's dark.
« Reply #1 on: 14 / January / 2024, 15:16:43 »
Quote from: Mlapse on 14 / January / 2024, 03:56:08
I have 2x S110 in use, one is 102B the other 103A.
They both run build:1.6.1-6200 and my script that shoots at a set interval.
Canon settings are identical.
 
Now, this is my second 102B that occasionally shuts down.
This always happens in the evening/early night, never in the morning or daytime.
It can go for weeks without this flaw or it can happen each week.
I've changed power supply, reformatted sd cards, but it keeps happening every now and then with the 102B
But usually i forget to make a romlog when this happens.

I've got one now and another in a few weeks, that one is still in the cam.
the shutdown happened at 17:14, the cam by then had an exposure of 4 seconds because it was already dark.

I do not understand what motion detect has to do with anything in my setup since i don't use it.
To be clear,
Code: [Select]
ASSERT!! MotionDetect.c Line 1135
Occured Time  2023:12:02 17:15:05
Task ID: 28704830
Task name: MotionVector0
SP: 0x0056A360
refers to some Canon motion detection, not CHDK. A lot of Canon's face detect and related code seems to run all the time. We have seen some crashes in MotionVector.c and/or MotionVector task, which like your seems to happen in particular shooting conditions. See this thread, especially the links at the end https://chdk.setepontos.com/index.php?topic=12523.20
This seems kinda similar (happening in/around shooting under particular but unclear conditions) but it's not clear how closely related: Yours in MotionVector *task*, MotionDetect.c, some of the others are in MotionVector.c and some other task, or MotionVector task in some other file. But Canon moves their code between files and renames things too.

If you can narrow down where in the script execution the crash happens (and post the relevant script code), that could be helpful. One way you could do this is by using LogCameraEvent calls at various points in the the script, so they will appear in the romlog. This will require a call_func_ptr call specific to that camera/firmware, which I can provide if you want to try this.

I'll have to look at those old threads and the s110 firmware a bit more to see if any of them look directly applicable.

If you google site:chdk.setepontos.com for MotionVector you might find additional threads
Logged
Don't forget what the H stands for.
*

Offline reyalp

  • ******
  • 14080
Re: sudden shutdown when it's dark.
« Reply #2 on: 14 / January / 2024, 21:41:28 »
Looked at this a little more. It doesn't seem to be directly related to the other "MotionVector" crashes I found.

Most of those (including one from you https://chdk.setepontos.com/index.php?topic=14586.msg148776#msg148776) seem to be ChaseFrame.c with a line number in the 271 range, or MotionVector.c around line 338. The line number varies between cams, but generally if it's the same code, the changes are pretty small.

The underlying cause seems like might still be somewhat related, it could be CHDK blocking execution for too long. Another possibility is CHDK overrides are apply some setting not expected with the camera settings (perhaps something like a 5 second exposure where the UI would only allow you to enter 1 at most?) So more information about what the script is doing could be helpful.

Details for anyone else who wants to try to debug it (addresses for s110 102b):
The assert happens in FUN_f83a6274 at f83a6570:
WaitForAnyEventFlagStrictly(DAT_0000e394,3,0x1388,"MotionDetect.c",0x46f);

0x1388 (5000 decimal) is the timeout which triggers the assert: 5 seconds. So the fact this happened when exposure was 4 (or more?) seconds makes some sense.

The only place I found eventflag DAT_0000e394 being set is a callback function FUN_f83a61b8. That callback is referenced in several places, but the most obvious candidate is FUN_f850b9f8, which is called just a few lines before the WaitEventFlagStrictly in FUN_f83a6274

FUN_f850b9f8 sets global PTR_00016d54 to the callback address, and DAT_00016d58 to a value which is probably a parameter for the callback.

The DAT_00016d58 callback is set and called in several places, but from a quick look, nothing jumps out as immediately connected to anything CHDK is doing, so not terribly promising for further analysis. It's certainly possible a deeper look would turn something up though.

edit:
One other thing we can see in the romlog
Code: [Select]
460594670: UI:Button:0x000009A3:PressSwTwo
...
460594730: UI:Button:0x000009A4:UnpressSwTwo
460594730: UI:Button:0x000009A2:UnpressSwOne
... last line
460599470: UI:DSIC:48,0

A shot was presumably started somewhere between ticks *4670 and 4730 (SwOne is half press, SwTwo is full), and the log ends at 9470, some 4.8s later, so the crash really was in/around shooting.
« Last Edit: 14 / January / 2024, 22:20:30 by reyalp »
Logged
Don't forget what the H stands for.
*

Offline Mlapse

  • *****
  • 583
  • S95 S110
Re: sudden shutdown when it's dark.
« Reply #3 on: 15 / January / 2024, 15:23:40 »
Maybe that log looked the same, it resulted in a communications error and was not happening when it was getting dark or exposure was over 1 second, but just after running for a while and that was something that would happen on any model cam i connected.
wasn't that related to exceeding the number of files on the sd card halting the connection?

This is what happens in this setup:
The script is triggered by an USB pulse with a 2 second duration, at the end of the 2 seconds the half press becomes a full press.
The script takes over and sets exposure length if it calculates longer than 1 second exposure is needed and it that case keeps the full press for the calculated time.
This will work flawlessly for the 103A cam, and very often for the 102B, but then:

The 102B cam stops functioning, i do not know if it in in the full press part of the longer than one second exposure shot, it looks like it is at start or during of the save moment at the end of the shot.
but only once i've seen the green 'save' led blinks for a minute or so before the cam shut down.
all the other times, the cam was just found dead after an hour or so and i can restart it without removing the power.

But I will place some LogCameraEvent in the script, i wish it would automatically save that log on boot, makes chances bigger that i do get it the first time :)

this part is all speculation:
What i also notice is that the cards that had a crash have some very slow readable blocks, and they were there to stay. halting or slowing systems when you tried to write there.
At first i thought that might be a reason the cam crashed, because it was unable to write in time or something like that.
Put in another brand card and that developed the same flaw within weeks.

Since i had also slow write experiences from cards that were in an earlyer life formatted to fat32, but kept slow parts...and old files.
I did a low level format with the sd foundation formatter, new repartition, quick format and chimp for a bootflag and the problem of slow writing is gone.
Now i'm considering that the crash might cause those blocks to get corrupted in some way.
Because the problem comes back again, i just don't know what evening the next one will be.

The cards i use now have been written to less than 10 times, so it's not a wear thing.
« Last Edit: 15 / January / 2024, 16:09:02 by Mlapse »
Logged
frustration is a key ingredient in progress
*

Offline reyalp

  • ******
  • 14080
Re: sudden shutdown when it's dark.
« Reply #4 on: 15 / January / 2024, 18:31:09 »
Quote from: Mlapse on 15 / January / 2024, 15:23:40
wasn't that related to exceeding the number of files on the sd card halting the connection?
Not the MotionVector crashes
Quote
This is what happens in this setup:
The script is triggered by an USB pulse with a 2 second duration, at the end of the 2 seconds the half press becomes a full press.
The script takes over and sets exposure length if it calculates longer than 1 second exposure is needed and it that case keeps the full press for the calculated time.
Can you post the actual code?
One possible explanation for the crash is CHDK tying up the CPU for too long, which the USB remote code can potentially do. Why 102b and 103a would differ is unclear, but the the CHDK ports might have difference, or the settings aren't actually completely identical, or the changes in the Canon code might be a factor (though my gut feeling is that's less likely)

Quote
But I will place some LogCameraEvent in the script
To use LogCamaraEvent from script, you'll need to call the function directly with call_func_ptr. From the funcs_by_name.csv, the address is 0xf80d3a9c for s110 101b and 102b, but is 0xf80d3a80 for 103c. So if you use the same script, you need to check get_buildinfo platsub.
The output from LogCameraEvent must be less than 64 characters. So putting this together, you could use something like the following (ixus175 included because that's what I tested on)
Code: [Select]
local bi = get_buildinfo()
if bi.platform == 's110' then
if bi.platsub == '103a' then
log_camera_event_ptr = 0xf80d3a80
elseif bi.platsub == '101b' or bi.platsub == '102b' then
log_camera_event_ptr = 0xf80d3a9c
end
elseif bi.platform == 'ixus175_elph180' then
-- all known use the same build
if bi.platsub == '100a' or bi.platsub == '100b' or bi.platsub == '100c' then
log_camera_event_ptr = 0xff834994
end
end
function log_camera_event(fmt,...)
-- pointer not defined for this platform, ignore
if not log_camera_event_ptr then
return
end
local s=fmt:format(...)
-- LogCameraEvent asserts if len > 63, truncate if needed
s = s:sub(1,63)
-- 0x20 logs with default settings, but includes neither SS: nor UI: prefix
call_func_ptr(log_camera_event_ptr,0x20,s)
end
log_camera_event('start %s %s',bi.platform,bi.platsub)
You can then sprinkle log_camera_event calls at significant points in your shooting loop. They are automatically timestamped in the camera log.

Quote
i wish it would automatically save that log on boot, makes chances bigger that i do get it the first time :)
You can get the romlog from Lua, see CHDK/SCRIPT/TEST/romlog.lua. Some logic would required to check if the log is new, since the most recent romlog stays in camera flash until overwritten, but you could just compare the first hundred characters in Lua or something.

Note the camera log (where LogCameraEvent goes) is normally not saved, except when there's a crash. You can also get it using uart redirection and the "ShowCameraLog" eventproc.

Quote
Now i'm considering that the crash might cause those blocks to get corrupted in some way.
From experience, crashes can certainly cause filesystem corruption, particularly around shooting. Causing lower level issues seems less likely to me, but not totally out of the question (cutting power can reportedly do that, but a camera crash with an assert should probably shut down the SD interface in a fairly normal way. OTOH, the card firmware likely has some knowledge of the filesystem for optimization, so who knows)
Logged
Don't forget what the H stands for.
*

Offline Mlapse

  • *****
  • 583
  • S95 S110
Re: sudden shutdown when it's dark.
« Reply #5 on: 24 / January / 2024, 11:08:44 »
Quote from: reyalp on 15 / January / 2024, 18:31:09
Can you post the actual code?
One possible explanation for the crash is CHDK tying up the CPU for too long, which the USB remote code can potentially do.
I haven't seen any crashes around the usb pulse, it always seems to happen at the end of exposure or file save
Why 102b and 103a would differ is unclear, but the the CHDK ports might have difference, or the settings aren't actually completely identical, or the changes in the Canon code might be a factor (though my gut feeling is that's less likely)

Quote
To use LogCamaraEvent from script, you'll need to call the function directly with call_func_ptr. From the funcs_by_name.csv, the address is 0xf80d3a9c for s110 101b and 102b, but is 0xf80d3a80 for 103c. So if you use the same script, you need to check get_buildinfo platsub.
The output from LogCameraEvent must be less than 64 characters. So putting this together, you could use something like the following (ixus175 included because that's what I tested on)
Code: [Select]
local bi = get_buildinfo()
if bi.platform == 's110' then
if bi.platsub == '103a' then
log_camera_event_ptr = 0xf80d3a80
elseif bi.platsub == '101b' or bi.platsub == '102b' then
log_camera_event_ptr = 0xf80d3a9c
end
elseif bi.platform == 'ixus175_elph180' then
-- all known use the same build
if bi.platsub == '100a' or bi.platsub == '100b' or bi.platsub == '100c' then
log_camera_event_ptr = 0xff834994
end
end
function log_camera_event(fmt,...)
-- pointer not defined for this platform, ignore
if not log_camera_event_ptr then
return
end
local s=fmt:format(...)
-- LogCameraEvent asserts if len > 63, truncate if needed
s = s:sub(1,63)
-- 0x20 logs with default settings, but includes neither SS: nor UI: prefix
call_func_ptr(log_camera_event_ptr,0x20,s)
end
log_camera_event('start %s %s',bi.platform,bi.platsub)
You can then sprinkle log_camera_event calls at significant points in your shooting loop. They are automatically timestamped in the camera log.

i'll start sprinkeling then, befor and after click'shoot_full'
any other suggestions?
« Last Edit: 24 / January / 2024, 14:21:13 by Mlapse »
Logged
frustration is a key ingredient in progress
*

Offline reyalp

  • ******
  • 14080
Re: sudden shutdown when it's dark.
« Reply #6 on: 24 / January / 2024, 14:03:30 »
Quote from: Mlapse on 24 / January / 2024, 11:08:44
i'll start sprinkeling then, befor and after click'shoot_full'
any other suggestions?
Yeah, my_shoot() seems like a good place to start. I'd probably do at the start of the function, after wait for get_shooting to be true, before and after click'shoot_full', and at the very end.
The one before shoot_full should log tv_goal.
Logged
Don't forget what the H stands for.
*

Offline Mlapse

  • *****
  • 583
  • S95 S110
Re: sudden shutdown when it's dark.
« Reply #7 on: 18 / February / 2024, 04:19:04 »
and naturally, when you ask for it, it doesn't happen.....

here is another rom log, but that is still from before inserting log_camera_event, so it looks the same as the one i posted before.
Logged
frustration is a key ingredient in progress
*

Offline reyalp

  • ******
  • 14080
Re: sudden shutdown when it's dark.
« Reply #8 on: 18 / February / 2024, 19:14:44 »
Quote from: Mlapse on 18 / February / 2024, 04:19:04
here is another rom log, but that is still from before inserting log_camera_event, so it looks the same as the one i posted before.
Seems to be the same crash (ASSERT!! MotionDetect.c Line 1135 in  MotionVector0 task) so it doesn't add much, but worth collecting so we know if it's always the same or different errors show up.
Logged
Don't forget what the H stands for.
*

Offline Mlapse

  • *****
  • 583
  • S95 S110
Re: sudden shutdown when it's dark.
« Reply #9 on: 29 / March / 2024, 13:36:30 »
Actually i should be happy.
But i find it a bit annoying that after the last low level format and adapting the code to catch the crash....nothing happened so far.
Logged
frustration is a key ingredient in progress
Pages: [1] 2   Go Up
« previous next »
 

Related Topics