Lua Scripting (lua.mo)

Started by dmilligan, March 29, 2015, 04:44:07 AM

Previous topic - Next topic

0 Members and 2 Guests are viewing this topic.

aprofiti

At the moment it doesn't seems to cause any problems with config's lib.
I'll check later the memory usage between older and newer implementation because at the moment I'm using a lot of stuffs to debug.

Maybe Lua garbage collector can be called after copying the new values from menu to config's data structure, before writing .cfg to card.
This will allow to free memory on each saving instead only on the first run if placed at the end of "lens.lua" initialization

a1ex

Updates:

- yet another DOF info fix (hopefully this time is correct; cross-checked with cBlur)
- Q button available on EOS M (long press); tested with editor.lua (which wasn't able to open the menu, to my knowledge - or did it have some hidden shortcut?); refactored for other models, but didn't automate this test yet (so there might be some camera models where this doesn't work)
- lens info (focus distance, focal length etc) updated outside LiveView! (available to Lua and all other modules)

The last item was discovered a long time ago, with low-level MPU communication functions. Only recently, given these QEMU advances, I could figure out how to call this with the high-level API (it was prop_request_change; had to identify the property and make sure I'm not passing bogus data).

There are several feature requests we had to turn down because of lack of lens info outside LiveView (mostly exposure-related). Now they are no longer pipe dreams :)

Also looking into the exposure override / aperture issue with FRSP (couldn't figure it out yet, but made some progress understanding the internals) and the LiveView exposure bug with manual lenses (to reproduce: with or without ML loaded, set Canon lens to f/22, then remove it, then use a manual lens in LiveView and take a picture).

dmilligan

Quoteor did it have some hidden shortcut?
The lua_touch branch. The editor is actually [the most] useful on that branch with an EOSM, there's an on screen touch keyboard.

a1ex

Cool, I should get that working in QEMU (as none of my cameras has touch screen). Startup logs from cameras with touch screen are welcome (they should cover you interacting with the touch screen, of course), outside LiveView (as LiveView is way too verbose).

A while ago I played with a 700D for a few weeks, and I had an (unfinished) attempt to make the ML menu touch-screen friendly, btw.

lojzik

Now there is no magiclantern-lua_fix.XXX.70D112 build. Is it bug or feature?
70D.112

garry23

@a1ex

Thanks for the continuous Lua Fix updates, including fixing my silly diffraction typo  :-[

Just loaded the latest fixes onto one of one EOSMs and diffraction looks good now.

The Q working in Menus is great, and I loved the real time feedback icon.

Got to look into any other updates to see if I can exploit these for photography  ;)

BTW the holy grail fix for me would include the following (typed here for fun, as I know all these are real challenges or unachievable):
- Seamless silent across all 'shutter' speed space, ie as a shoot option
- Moving EOSM lenses, and potentially more refined than we currently can
- More refined lens position feedback

Once again, thanks for the latest push.

Cheers

Garry

aprofiti

Camera 50D

Got errors with manual_lens_info branch Feb19 (has Feb17 lua_fix changes):

===============================================================================
ML/SCRIPTS/API_TEST.LUA - 2018-2-19 12:39:29
===============================================================================

Strict mode tests...
Strict mode tests passed.

Generic tests...
arg = table:
  [0] = "API_TEST.LUA"
camera = table:
  shutter = table:
    raw = 101
    apex = 5.625
    ms = 20
    value = 0.020263
  aperture = table:
    raw = 32
    apex = 3.
    value = 2.8
    min = table:
      raw = 32
      apex = 3.
      value = 2.8
    max = table:
      raw = 88
      apex = 10.
      value = 32
  iso = table:
    raw = 104
    apex = 9.
    value = 1600
  ec = table:
    raw = 0
    value = 0
  flash_ec = table:
    raw = 0
    value = 0
  kelvin = 5200
  mode = 3
  metering_mode = 4
  drive_mode = 0
  model = "Canon EOS 50D"
  model_short = "50D"
  firmware = "1.0.9"
  temperature = 152
  gui = table:
    menu = false
    play = false
    play_photo = false
    play_movie = false
    qr = false
    idle = true
  bulb = function: p
  burst = function: p
  wait = function: p
  shoot = function: p
  reboot = function: p
event = table:
  pre_shoot = nil
  post_shoot = nil
  shoot_task = nil
  seconds_clock = nil
  keypress = nil
  custom_picture_taking = nil
  intervalometer = nil
  config_save = nil
console = table:
  show = function: p
  hide = function: p
  write = function: p
  clear = function: p
lv = table:
  enabled = false
  paused = false
  running = false
  zoom = 1
  overlays = false
  start = function: p
  stop = function: p
  info = function: p
  wait = function: p
  pause = function: p
  resume = function: p
lens = table:
  name = "17-50mm"
  focal_length = 17
  focus_distance = 0
  hyperfocal = 5466
  dof_near = 11139225
  dof_far = 1000000
  af = true
  af_mode = 514
  autofocus = function: p
  focus = function: p
display = table:
  idle = nil
  height = 480
  width = 720
  rect = function: p
  off = function: p
  pixel = function: p
  print = function: p
  line = function: p
  circle = function: p
  on = function: p
  screenshot = function: p
  clear = function: p
  load = function: p
  notify_box = function: p
  draw = function: p
key = table:
  last = 20
  press = function: p
  wait = function: p
menu = table:
  visible = false
  get = function: p
  select = function: p
  new = function: p
  close = function: p
  open = function: p
  block = function: p
  set = function: p
movie = table:
  recording = false
  stop = function: p
  start = function: p
dryos = table:
  clock = 17
  ms_clock = 17951
  image_prefix = "IMG_"
  dcim_dir = table:
    exists = true
    create = function: p
    children = function: p
    files = function: p
    parent = table:
      exists = true
      create = function: p
      children = function: p
      files = function: p
      parent = table:
        exists = true
        create = function: p
        children = function: p
        files = function: p
        parent = nil
        path = "A:/"
      path = "A:/DCIM/"
    path = "A:/DCIM/102CANON/"
  config_dir = table:
    exists = true
    create = function: p
    children = function: p
    files = function: p
    parent = table:
      exists = true
      create = function: p
      children = function: p
      files = function: p
      parent = table:
        exists = true
        create = function: p
        children = function: p
        files = function: p
        parent = nil
        path = "A:/"
      path = "ML/"
    path = "ML/SETTINGS/"
  ml_card = table:
    cluster_size = 4096
    drive_letter = "A"
    file_number = 422
    folder_number = 102
    free_space = 818432
    type = "CF"
    _card_ptr = userdata
    path = "A:/"
  shooting_card = table:
    cluster_size = 4096
    drive_letter = "A"
    file_number = 422
    folder_number = 102
    free_space = 818432
    type = "CF"
    _card_ptr = userdata
    path = "A:/"
  date = table:
    isdst = false
    min = 39
    yday = 1
    sec = 30
    wday = 65
    year = 2018
    day = 19
    month = 2
    hour = 12
  remove = function: p
  directory = function: p
  rename = function: p
  call = function: p
interval = table:
  time = 10
  count = 0
  running = false
  stop = function: p
battery = table:
function not available on this camera
stack traceback:
[C]: in ?
[C]: in for iterator 'for iterator'
ML/SCRIPTS/LIB/logger.lua:125: in function 'logger.serialize'
ML/SCRIPTS/API_TEST.LUA:36: in function <ML/SCRIPTS/API_TEST.LUA:35>
[C]: in function 'xpcall'
ML/SCRIPTS/API_TEST.LUA:35: in function 'print_table'
ML/SCRIPTS/API_TEST.LUA:81: in function 'generic_tests'
ML/SCRIPTS/API_TEST.LUA:1338: in function 'api_tests'
ML/SCRIPTS/API_TEST.LUA:1364: in main chunktask = table:
  yield = function: p
  create = function: p
property = table:
Generic tests completed.

Module tests...
Testing file I/O...
Copy test: autoexec.bin -> tmp.bin
Copy test OK
Append test: tmp.txt
Append test OK
Rename test: apple.txt -> banana.txt
Rename test OK
Rename test: apple.txt -> ML/banana.txt
Rename test OK
File I/O tests completed.

Testing Canon GUI functions...
Enter MENU mode...
Enter MENU mode...
Enter PLAY mode...
Exit PLAY mode...
Enter MENU mode...
Enter PLAY mode...
Enter MENU mode...
Enter MENU mode...
Exit MENU mode...
Start LiveView...
Enter MENU mode...
Enter PLAY mode...
Enter PLAY mode...
Enter MENU mode...
Enter MENU mode...
Enter MENU mode...
Exit MENU mode...
Enter MENU mode...
Exit MENU mode...
Pause LiveView...
Enter MENU mode...
Exit MENU mode...
Enter MENU mode...
Enter PLAY mode...
Enter PLAY mode...
Enter PLAY mode...
Enter MENU mode...
Enter MENU mode...
Exit MENU mode...
Pause LiveView...
Enter MENU mode...
Enter MENU mode...
Enter MENU mode...
Exit MENU mode...
Pause LiveView...
Enter MENU mode...
Enter MENU mode...
Enter MENU mode...
Exit MENU mode...
Enter PLAY mode...
Enter MENU mode...
Enter MENU mode...
Enter PLAY mode...
Enter MENU mode...
Enter PLAY mode...
Exit PLAY mode...
Pause LiveView...
Enter PLAY mode...
Exit PLAY mode...
Pause LiveView...
Enter PLAY mode...
Enter PLAY mode...
Exit PLAY mode...
Enter MENU mode...
Exit MENU mode...
Pause LiveView...
Resume LiveView...
Enter MENU mode...
Enter PLAY mode...
Enter MENU mode...
Enter MENU mode...
Enter MENU mode...
Exit MENU mode...
Pause LiveView...
Enter MENU mode...
Enter PLAY mode...
Enter MENU mode...
Exit MENU mode...
Pause LiveView...
Enter MENU mode...
Exit MENU mode...
Enter MENU mode...
Enter PLAY mode...
Enter MENU mode...
Enter MENU mode...
Exit MENU mode...
Enter MENU mode...
Enter MENU mode...
Exit MENU mode...
Pause LiveView...
Enter MENU mode...
Enter MENU mode...
Enter PLAY mode...
Exit PLAY mode...
Pause LiveView...
Enter MENU mode...
Canon GUI tests completed.

Testing ML menu API...
Menu tests completed.

Testing picture taking functions...
Snap simulation test...
Single picture...


Can find picture in CF but assertion is triggered:



Same errors with latest lua_fix nightly (Run some quick tests a month ago and if I remember correctly api_test was failing also before).

Camera in M mode, lens AF swith ON and 0,7GB free space on CF.

Edit: filename _MG_0424.CR2 , Should I try to reset Canon's setting?

a1ex

Yeah, this test is good at finding issues, though it only does so with the particular combination of Canon settings you have set when running it :D

aprofiti

Tested again with lua_fix build after camera's settings reset:

===============================================================================
ML/SCRIPTS/API_TEST.LUA - 2018-2-19 13:08:53
===============================================================================

Strict mode tests...
Strict mode tests passed.

Generic tests...
arg = table:
  [0] = "API_TEST.LUA"
camera = table:
  shutter = table:
    raw = 112
    apex = 7.
    ms = 8
    value = 0.007812
  aperture = table:
    raw = 48
    apex = 5.
    value = 5.6
    min = table:
      raw = 32
      apex = 3.
      value = 2.8
    max = table:
      raw = 88
      apex = 10.
      value = 32
  iso = table:
    raw = 0
    apex = 0
    value = 0
  ec = table:
    raw = 0
    value = 0
  flash_ec = table:
    raw = 0
    value = 0
  kelvin = 5200
  mode = 3
  metering_mode = 3
  drive_mode = 0
  model = "Canon EOS 50D"
  model_short = "50D"
  firmware = "1.0.9"
  temperature = 158
  gui = table:
    menu = false
    play = false
    play_photo = false
    play_movie = false
    qr = false
    idle = true
  bulb = function: p
  burst = function: p
  reboot = function: p
  shoot = function: p
  wait = function: p
event = table:
  pre_shoot = nil
  post_shoot = nil
  shoot_task = nil
  seconds_clock = nil
  keypress = nil
  custom_picture_taking = nil
  intervalometer = nil
  config_save = nil
console = table:
  write = function: p
  hide = function: p
  clear = function: p
  show = function: p
lv = table:
  enabled = false
  paused = false
  running = false
  zoom = 1
  overlays = false
  resume = function: p
  stop = function: p
  start = function: p
  info = function: p
  wait = function: p
  pause = function: p
lens = table:
  name = "17-50mm"
  focal_length = 32
  focus_distance = 0
  hyperfocal = 9688
  dof_near = 1552657632
  dof_far = 1000000
  af = true
  af_mode = 0
  focus = function: p
  autofocus = function: p
display = table:
  idle = nil
  height = 480
  width = 720
  line = function: p
  rect = function: p
  on = function: p
  print = function: p
  draw = function: p
  pixel = function: p
  clear = function: p
  screenshot = function: p
  load = function: p
  circle = function: p
  notify_box = function: p
  off = function: p
key = table:
  last = 20
  press = function: p
  wait = function: p
menu = table:
  visible = false
  new = function: p
  open = function: p
  set = function: p
  close = function: p
  block = function: p
  select = function: p
  get = function: p
movie = table:
  recording = false
  start = function: p
  stop = function: p
dryos = table:
  clock = 47
  ms_clock = 47855
  image_prefix = "IMG_"
  dcim_dir = table:
    exists = true
    create = function: p
    children = function: p
    files = function: p
    parent = table:
      exists = true
      create = function: p
      children = function: p
      files = function: p
      parent = table:
        exists = true
        create = function: p
        children = function: p
        files = function: p
        parent = nil
        path = "A:/"
      path = "A:/DCIM/"
    path = "A:/DCIM/102CANON/"
  config_dir = table:
    exists = true
    create = function: p
    children = function: p
    files = function: p
    parent = table:
      exists = true
      create = function: p
      children = function: p
      files = function: p
      parent = table:
        exists = true
        create = function: p
        children = function: p
        files = function: p
        parent = nil
        path = "A:/"
      path = "ML/"
    path = "ML/SETTINGS/"
  ml_card = table:
    cluster_size = 4096
    drive_letter = "A"
    file_number = 425
    folder_number = 102
    free_space = 746144
    type = "CF"
    path = "A:/"
    _card_ptr = userdata
  shooting_card = table:
    cluster_size = 4096
    drive_letter = "A"
    file_number = 425
    folder_number = 102
    free_space = 746144
    type = "CF"
    path = "A:/"
    _card_ptr = userdata
  date = table:
    min = 8
    year = 2018
    day = 19
    wday = 65
    month = 2
    yday = 1
    sec = 54
    hour = 13
    isdst = false
  rename = function: p
  remove = function: p
  directory = function: p
  call = function: p
interval = table:
  time = 10
  count = 0
  running = false
  stop = function: p
battery = table:
function not available on this camera
stack traceback:
[C]: in ?
[C]: in for iterator 'for iterator'
ML/SCRIPTS/LIB/logger.lua:125: in function 'logger.serialize'
ML/SCRIPTS/API_TEST.LUA:36: in function <ML/SCRIPTS/API_TEST.LUA:35>
[C]: in function 'xpcall'
ML/SCRIPTS/API_TEST.LUA:35: in function 'print_table'
ML/SCRIPTS/API_TEST.LUA:81: in function 'generic_tests'
ML/SCRIPTS/API_TEST.LUA:1338: in function 'api_tests'
ML/SCRIPTS/API_TEST.LUA:1364: in main chunktask = table:
  create = function: p
  yield = function: p
property = table:
Generic tests completed.

Module tests...
Testing file I/O...
Copy test: autoexec.bin -> tmp.bin
Copy test OK
Append test: tmp.txt
Append test OK
Rename test: apple.txt -> banana.txt
Rename test OK
Rename test: apple.txt -> ML/banana.txt
Rename test OK
File I/O tests completed.

Testing Canon GUI functions...
Enter MENU mode...
Enter PLAY mode...
Enter PLAY mode...
Enter PLAY mode...
Enter MENU mode...
Enter PLAY mode...
Enter MENU mode...
Enter MENU mode...
Exit MENU mode...
Start LiveView...
Start LiveView...
Enter MENU mode...
Enter MENU mode...
Enter PLAY mode...
Enter PLAY mode...
Enter MENU mode...
Enter PLAY mode...
Enter MENU mode...
Enter PLAY mode...
Enter MENU mode...
Exit MENU mode...
Start LiveView...
Start LiveView...
Enter PLAY mode...
Exit PLAY mode...
Enter MENU mode...
Enter PLAY mode...
Enter PLAY mode...
Enter PLAY mode...
Exit PLAY mode...
Start LiveView...
Enter PLAY mode...
Exit PLAY mode...
Enter PLAY mode...
Enter PLAY mode...
Enter MENU mode...
Exit MENU mode...
Start LiveView...
Start LiveView...
Enter PLAY mode...
Enter PLAY mode...
Enter PLAY mode...
Enter MENU mode...
Exit MENU mode...
Start LiveView...
Start LiveView...
Start LiveView...
Enter PLAY mode...
Exit PLAY mode...
Start LiveView...
Start LiveView...
Enter MENU mode...
Exit MENU mode...
Enter PLAY mode...
Enter PLAY mode...
Enter PLAY mode...
Exit PLAY mode...
Enter MENU mode...
Enter PLAY mode...
Enter MENU mode...
Exit MENU mode...
Enter MENU mode...
Exit MENU mode...
Start LiveView...
Start LiveView...
Enter PLAY mode...
Enter PLAY mode...
Enter MENU mode...
Enter PLAY mode...
Enter MENU mode...
Exit MENU mode...
Enter MENU mode...
Enter MENU mode...
Enter PLAY mode...
Exit PLAY mode...
Start LiveView...
Enter PLAY mode...
Enter PLAY mode...
Canon GUI tests completed.

Testing ML menu API...
Menu tests completed.

Testing picture taking functions...
Snap simulation test...
Single picture...
A:/DCIM/102CANON/IMG_0426.CR2: 20705356
A:/DCIM/102CANON/IMG_0426.JPG not found.
Two burst pictures...
Ideally, the camera should be in some continuous shooting mode (not checked).
A:/DCIM/102CANON/ABC_0427.CR2: 20686900
A:/DCIM/102CANON/ABC_0427.JPG not found.
A:/DCIM/102CANON/ABC_0428.CR2: 20690368
A:/DCIM/102CANON/ABC_0428.JPG not found.
Bracketed pictures...
A:/DCIM/102CANON/IMG_0429.CR2: 19010223
A:/DCIM/102CANON/IMG_0429.JPG not found.
A:/DCIM/102CANON/IMG_0430.CR2: 20691711
A:/DCIM/102CANON/IMG_0430.JPG not found.
A:/DCIM/102CANON/IMG_0431.CR2: 21265995
A:/DCIM/102CANON/IMG_0431.JPG not found.
Bulb picture...
Elapsed time: 11599
A:/DCIM/102CANON/IMG_0432.CR2: 11809061
A:/DCIM/102CANON/IMG_0432.JPG not found.
Picture taking tests completed.

Testing multitasking...
Only one task allowed to interrupt...
Main task yielding.
Task C started.
Task C finished.
Main task back.
Main task yielding.
Task C started.
Task C finished.
Main task back.
Main task yielding.
Task C started.
Task C finished.
Main task back.
Main task yielding.
Task C started.
Task C finished.
Main task back.
Main task yielding.
Task C started.
Task C finished.
Main task back.
Main task yielding.
Task C started.
Task C finished.
Main task back.
Main task yielding.
Task C started.
Task C finished.
Main task back.
Main task yielding.
Task C started.
Task C finished.
Main task back.
Main task yielding.
Task C started.
Task C finished.
Main task back.
Main task yielding.
Task C started.
Task C finished.
Main task back.
Multitasking tests completed.

Testing half-shutter...

This time it taken more pictures but got an assert on test_keys() (I could hear half-shutter beep)



a1ex

Reproduced in QEMU. The console also flickers a lot during the test - does it happen on real hardware?

edit: possibly false alarm, it was a bug in my emulation, or it might be the 50D MPU that behaves in a different way; can you print key.last right before the assertion?

aprofiti

Quote from: a1ex on February 19, 2018, 05:57:12 PM
Reproduced in QEMU. The console also flickers a lot during the test - does it happen on real hardware?

Yes, It flicker also on real hardware (a little bit faster but it's still annoiyng) it may be canon's code redrawing photo info display, It doesn't flicker when in photo review mode.
It's me or some times ago console was displayed fullscreen and semi-transparent?

a1ex

Yeah, I've been playing with the layout a bit. It should still be semi-transparent in LiveView and PLAY mode (whenever you have an image behind it). It's no longer true?

Thought to make it a bit larger in ML menu, and have it go out of the way as you navigate (for example, if you move the scroll bar to the bottom half, the console should automatically go to the top side).

aprofiti

It's semi transparent in PLAY mode (I don't remember if it was larger) an LV (moves up to avoid cover bottom bar info)
In Photo info it's not semi-transparent and it flickers a lot.
In Ml menu it get resized (show last 3 lines) and cover bottom bar (menu's .info and .info2)

a1ex

In photo mode, there's nothing behind to make use of transparency (possibly just the last LiveView frame or last viewed photo, but transparency wouldn't make much sense to me in this case). The bitmap overlay is only one, you can't have multiple transparent layers; you can only make parts of it transparent to see the image overlay (LiveView etc).

Got a quick test for you to run, from the dm-spy-experiments branch, compiled with CONFIG_DEBUG_INTERCEPT=y -- place this code in debug.c and select Don't click me:

static void run_test()
{
    msleep(1000);
    SetGUIRequestMode(GUIMODE_PLAY);
    msleep(1000);
    debug_intercept();
    msleep(1000);
    SW1(1,100);
    SW1(0,100);
    msleep(1000);
    debug_intercept();
}


It goes to PLAY mode, "presses" half-shutter from there (just like the Lua half-shutter test does), and records Canon's debug messages, including MPU messages.

aprofiti

I can't do at the moment. I'll try to report it before going to sleep.

One thing I noticed some time ago and stilo presente, is a very high CPU usage in Photo display maybe related to redrawing. Can refresh rate be reduced or stopped/starded on demand to save battery?

a1ex

Most likely yes - there is a similar hack done while recording raw video. Didn't really look too much into the GUI subsystem, partly because we didn't have the tools to understand how it works (but now we have them).

aprofiti

Quote from: a1ex on February 19, 2018, 05:57:12 PM
can you print key.last right before the assertion?
It prints "2"

Quote from: a1ex on February 19, 2018, 06:30:40 PM
Got a quick test for you to run, from the dm-spy-experiments branch, compiled with CONFIG_DEBUG_INTERCEPT=y -- place this code in debug.c and select Don't click me:

"Make zip" fails and also lua is not compiled
../../scripts/lib/../../src/config.c:908:14: error: 'DISPLAY_IS_ON' undeclared (first use in this function)
         if (!DISPLAY_IS_ON) beep();
              ^
make[5]: *** [../../scripts/lib/config.o] Error 1

..............

[ MKDIR    ]   ML directory structure...
cp ../modules/*/*.mo /Users/alex/Desktop/pullML/tmp/platform/50D.109/zip/ML/modules/
/Library/Developer/CommandLineTools/usr/bin/make -C ../../installer/50D.109 autoexec-fir.bin
[ VERSION  ]   ../../platform/50D.109/version.bin
make[1]: *** No rule to make target `../../src/mutex.h', needed by `installer.o'.  Stop.
make: *** [installer_check] Error 2


But I copied ML files from zip folder and worked.
Her is the log file. Hope it helps


a1ex

The mutex.h error suggests it needs a "make clean" (the Makefiles won't figure this out on their own).

Not sure why it even attempts to build ../../scripts/lib/config.o (will check later).

Just FYI - the annotated MPU events from this log:

1D763>    PropMgr:0008f90c:00:00: *** mpu_send(08 06 04 16 01 00 00), from ff85c124                  ; PROP_REMOTE_SW1
1DF1F> **INT-36h*:0008f974:00:00: *** mpu_recv(06 05 06 09 00 00), from ff97763c                     ; BGMT_UNPRESS_ZOOM_IN
1E0D2> **INT-36h*:0008f974:00:00: *** mpu_recv(06 05 06 0a 00 00), from ff97763c                     ; BGMT_UNPRESS_ZOOM_OUT
1F824> **INT-36h*:0008f974:00:00: *** mpu_recv(24 22 0a 08 5f 00 01 00 01 03 a0 10 00 50 01 01 58 20 25 01 01 00 68 04 01 00 17 01 00 00 00 00 00 00 00), from ff97763c ; PD_NotifyOlcInfoChanged
1FDA7> **INT-36h*:0008f974:00:00: *** mpu_recv(06 05 04 00 00 01), from ff97763c                     ; NotifyGUIEvent
1FF2A> **INT-36h*:0008f974:00:00: *** mpu_recv(06 05 03 17 99 00), from ff97763c                     ; PROP_EFIC_TEMP
22679>    PropMgr:0008f90c:00:00: *** mpu_send(08 06 00 00 04 00 00), from ff85c124                  ; Complete WaitID = NotifyGUIEvent
24A1F> **INT-36h*:0008f974:00:00: *** mpu_recv(06 04 05 00 00), from ff97763c                        ; EVENTID_METERING_START_SW1ON
2F3D8> **INT-36h*:0008f974:00:00: *** mpu_recv(10 0f 0a 08 41 00 02 00 01 02 e8 00 00 00 00 00), from ff97763c ; PD_NotifyOlcInfoChanged
2FA59> **INT-36h*:0008f974:00:00: *** mpu_recv(0c 0b 0a 08 00 02 01 02 00 00 80 00), from ff97763c   ; PD_NotifyOlcInfoChanged
34175>    PropMgr:0008f90c:00:00: *** mpu_send(08 06 04 16 00 00 00), from ff85c124                  ; PROP_REMOTE_SW1
3446B> **INT-36h*:0008f974:00:00: *** mpu_recv(06 05 04 16 00 00), from ff97763c                     ; PROP_REMOTE_SW1
36BC8>    PropMgr:0008f90c:00:00: *** mpu_send(06 05 03 19 01 00), from ff85c124                     ; PROP_TFT_STATUS
4B556> **INT-36h*:0008f974:00:00: *** mpu_recv(06 04 05 0b 00), from ff97763c                        ; EVENTID_METERING_TIMER_START_SW1OFF
4C05F> **INT-36h*:0008f974:00:00: *** mpu_recv(0e 0d 0a 08 40 00 01 02 e3 00 00 00 00 00), from ff97763c ; PD_NotifyOlcInfoChanged
4CA64> **INT-36h*:0008f974:00:00: *** mpu_recv(0a 08 0a 08 01 00 03 00 00), from ff97763c            ; PD_NotifyOlcInfoChanged
59F3B>    PropMgr:0008f90c:00:00: *** mpu_send(06 05 03 19 01 00), from ff85c124                     ; PROP_TFT_STATUS
B932D>    PropMgr:0008f90c:00:00: *** mpu_send(06 05 03 19 00 00), from ff85c124                     ; PROP_TFT_STATUS


Reproduced the issue using the info from this log.

aprofiti

Quote from: a1ex on February 20, 2018, 12:59:50 AM
The mutex.h error suggests it needs a "make clean" (the Makefiles won't figure this out on their own).
Pretty sure I have done it. Retried "make clean" from /50D.109 and also from root directory, but it show up again.

Quote from: a1ex on February 20, 2018, 12:59:50 AM
Reproduced the issue using the info from this log.
Can you explain what's wrong? :)

a1ex

Quote
Pretty sure I have done it. Retried "make clean" from /50D.109 and also from root directory, but it show up again.

Try this patch:

--- a/platform/Makefile.platform.extras
+++ b/platform/Makefile.platform.extras
@@ -52,2 +52,3 @@
installer_check: | autoexec.bin
+       $(MAKE) -C $(INSTALLER_DIR)/$(ML_MODEL_DIR) clean
        $(MAKE) -C $(INSTALLER_DIR)/$(ML_MODEL_DIR) autoexec-fir.bin


QuoteCan you explain what's wrong? :)

It's not exactly clear to me either. That 2 is the half-shutter unpress event; 1 is half-shutter press (module.h). Does it always happen on the first iteration, or it's random?

At first I've assumed it must be EVENTID_METERING_TIMER_START (aka half-shutter unpress) somehow being triggered on the "press" event, but that doesn't happen in your log, so I'm a bit puzzled.

aprofiti

Patch works but I had to check indentation (tab character) otherwise makefile won't works:
diff --git a/platform/Makefile.platform.extras b/platform/Makefile.platform.extras
--- a/platform/Makefile.platform.extras
+++ b/platform/Makefile.platform.extras
@@ -50,6 +50,7 @@
# do not actually build the FIR - just the plain binary
# also clean the installer directory afterwards; we are not going to use the results, just make sure it builds
installer_check: | autoexec.bin
+ $(MAKE) -C $(INSTALLER_DIR)/$(ML_MODEL_DIR) clean
$(MAKE) -C $(INSTALLER_DIR)/$(ML_MODEL_DIR) autoexec-fir.bin
$(MAKE) -C $(INSTALLER_DIR)/$(ML_MODEL_DIR) clean



Quote from: a1ex on February 20, 2018, 01:41:08 AM
It's not exactly clear to me either. That 2 is the half-shutter unpress event; 1 is half-shutter press (module.h). Does it always happen on the first iteration, or it's random?

Do you want me to run the test more times to see if appears in other logs?

aprofiti

Run Stubs Api tests in dm-spy-experiment and lua_fix.
Only selftest module loaded and movie record enabled.

[Pass] is_play_mode() => 0x1
[Pass] src = fio_malloc(size) => 0x421140ac
[Pass] dst = fio_malloc(size) => 0x429180b8
[Pass] memcmp(dst, src, 4097) => 0xffffff31
[Pass] edmac_memcpy(dst, src, 4097) => 0x429180b8
[Pass] memcmp(dst, src, 4097) => 0x0
[Pass] edmac_memcpy(dst, src, 4097) => 0x429180b8
[Pass] memcmp(dst, src, size) => 0xffffff41
[Pass] edmac_memcpy(dst, src, size) => 0x429180b8
[Pass] memcmp(dst, src, size) => 0x0
[Pass] memcmp(dst, src, size) => 0xaf
[Pass] edmac_memcpy_start(dst, src, size) => 0x429180b8
       dt => 0x300a
[Pass] copied => 0x401000
[Pass] copied => 0x401000
[Pass] copied => 0x401000
[Pass] memcmp(dst, src, copied) => 0x0
[Pass] memcmp(dst, src, copied + 16) => 0xffffff7f
       edmac_memcpy_finish()
       free(src)
       free(dst)
Cache test A (EDMAC on BMP buffer)...
[Pass] bmp = bmp_load("ML/CROPMKS/CINESCO2.BMP", 1) => 0x1050d0
[Pass] old => 0x0
[Pass] irq => 0xc0
[Pass] differences => 0x660
[Pass] old => 0x0
[Pass] irq => 0xc0
[Pass] differences => 0x0
Cache test B (FIO on 8K buffer)...
[Pass] tries[0] => 0x10f
[Pass] tries[1] => 0xe5
[Pass] tries[2] => 0xf8
[Pass] tries[3] => 0xfc
[Pass] failr[0] => 0x7c
[Pass] failw[0] => 0x55
[Pass] failr[1] => 0x61
[Pass] failw[1] => 0x0
[Pass] failr[2] => 0x0
[Pass] failw[2] => 0x58
[Pass] failr[3] => 0x0
[Pass] failw[3] => 0x0
       times[0] / tries[0] => 0x1a
       times[1] / tries[1] => 0x1d
       times[2] / tries[2] => 0x19
       times[3] / tries[3] => 0x1c
Cache tests finished.

[Pass] f = FIO_CreateFile("test.dat") => 0x3
[Pass] FIO_WriteFile(f, (void*)0xFF000000, 0x10000) => 0x10000
[Pass] FIO_WriteFile(f, (void*)0xFF000000, 0x10000) => 0x10000
       FIO_CloseFile(f)
[Pass] FIO_GetFileSize("test.dat", &size) => 0x0
[Pass] size => 0x20000
[Pass] p = (void*)_alloc_dma_memory(0x20000) => 0x40990038
[Pass] f = FIO_OpenFile("test.dat", O_RDONLY | O_SYNC) => 0x3
[Pass] FIO_ReadFile(f, p, 0x20000) => 0x20000
       FIO_CloseFile(f)
       _free_dma_memory(p)
[Pass] count => 0x3a98
[Pass] buf = fio_malloc(0x1000000) => 0x421140ac
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000000
[Pass] f = FIO_OpenFile("test.dat", O_RDWR | O_SYNC) => 0x3
[Pass] FIO_SeekSkipFile(f, 0, SEEK_END) => 0x82000000
[Pass] FIO_WriteFile(f, buf, 0x10) => 0x10
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_END) => 0x81fffff0
[Pass] FIO_WriteFile(f, buf, 0x30) => 0x30
[Pass] FIO_SeekSkipFile(f, 0x20, SEEK_SET) => 0x20
[Pass] FIO_SeekSkipFile(f, 0x30, SEEK_CUR) => 0x50
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_CUR) => 0x30
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000020
[Pass] is_file("test.dat") => 0x1
[Pass] FIO_RemoveFile("test.dat") => 0x0
[Pass] is_file("test.dat") => 0x0
[Pass] SetTimerAfter(0, timer_cbr, overrun_cbr, 0) => 0x15
[Pass] timer_func => 0x2
[Pass] SetTimerAfter(1000, timer_cbr, overrun_cbr, 0) => 0x1d7f4
       msleep(900)
[Pass] timer_func => 0x0
       msleep(200)
[Pass] timer_func => 0x1
[Pass] ABS((timer_time/1000 - t0) - 1000) => 0x6
[Pass] ABS((timer_arg - ta0) - 1000) => 0xa
[Pass] timer = SetTimerAfter(1000, timer_cbr, overrun_cbr, 0) => 0x1d7f6
       msleep(400)
       CancelTimer(timer)
[Pass] timer_func => 0x0
       msleep(1500)
[Pass] timer_func => 0x0
[Pass] SetHPTimerAfterNow(0, timer_cbr, overrun_cbr, 0) => 0x15
[Pass] timer_func => 0x2
[Pass] SetHPTimerAfterNow(100000, timer_cbr, overrun_cbr, 0) => 0x182
       msleep(90)
[Pass] timer_func => 0x0
       msleep(20)
[Pass] timer_func => 0x1
[Pass] ABS(DeltaT(timer_time, t0) - 100000) => 0x112
[Pass] ABS(DeltaT(timer_arg, ta0) - 100000) => 0xe3
[Pass] ABS((get_us_clock_value() - t0) - 110000) => 0x1f
[Pass] SetHPTimerAfterNow(90000, next_tick_cbr, overrun_cbr, 0) => 0x184
       msleep(80)
[Pass] timer_func => 0x0
       msleep(20)
[Pass] timer_func => 0x3
       msleep(80)
[Pass] timer_func => 0x3
       msleep(20)
[Pass] timer_func => 0x1
[Pass] ABS(DeltaT(timer_time, t0) - 300000) => 0xc1
[Pass] ABS(DeltaT(timer_arg, ta0) - 300000) => 0x91
[Pass] ABS((get_us_clock_value() - t0) - 310000) => 0x39
       t0 = *(uint32_t*)0xC0242014 => 0x2c9bd
       msleep(250)
       t1 = *(uint32_t*)0xC0242014 => 0x6899e
[Pass] ABS(MOD(t1-t0, 1048576)/1000 - 250) => 0x5
       LoadCalendarFromRTC( &now )
       s0 = now.tm_sec => 0x18
       Date/time: 2018/02/21 12:40:24
       msleep(1500)
       LoadCalendarFromRTC( &now )
       s1 = now.tm_sec => 0x1a
[Pass] MOD(s1-s0, 60) => 0x2
[Pass] MOD(s1-s0, 60) => 0x2
       m0 = MALLOC_FREE_MEMORY => 0x22bd0
[Pass] p = (void*)_malloc(50*1024) => 0x106e18
[Pass] CACHEABLE(p) => 0x106e18
       m1 = MALLOC_FREE_MEMORY => 0x163d0
       _free(p)
       m2 = MALLOC_FREE_MEMORY => 0x22bd0
[Pass] ABS((m0-m1) - 50*1024) => 0x0
[Pass] ABS(m0-m2) => 0x0
       m0 = GetFreeMemForAllocateMemory() => 0x3a9e20
[Pass] p = (void*)_AllocateMemory(256*1024) => 0x98fff8
[Pass] CACHEABLE(p) => 0x98fff8
       m1 = GetFreeMemForAllocateMemory() => 0x369e14
       _FreeMemory(p)
       m2 = GetFreeMemForAllocateMemory() => 0x3a9e20
[Pass] ABS((m0-m1) - 256*1024) => 0xc
[Pass] ABS(m0-m2) => 0x0
       m01 = MALLOC_FREE_MEMORY => 0x22bd0
       m02 = GetFreeMemForAllocateMemory() => 0x3a9e20
[Pass] p = (void*)_alloc_dma_memory(256*1024) => 0x40990038
[Pass] UNCACHEABLE(p) => 0x40990038
[Pass] CACHEABLE(p) => 0x990038
[Pass] UNCACHEABLE(CACHEABLE(p)) => 0x40990038
       _free_dma_memory(p)
[Pass] p = (void*)_shoot_malloc(24*1024*1024) => 0x4211408c
[Pass] UNCACHEABLE(p) => 0x4211408c
       _shoot_free(p)
       m11 = MALLOC_FREE_MEMORY => 0x22bd0
       m12 = GetFreeMemForAllocateMemory() => 0x3a9e20
[Pass] ABS(m01-m11) => 0x0
[Pass] ABS(m02-m12) => 0x0
[Pass] suite = shoot_malloc_suite_contig(24*1024*1024) => 0x990028
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x1
[Pass] suite->size => 0x1800000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x99004c
[Pass] chunk->signature => 'MemChunk'
[Pass] chunk->size => 0x1800000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x42114088
[Pass] UNCACHEABLE(p) => 0x42114088
       shoot_free_suite(suite); suite = 0; chunk = 0;
[Pass] suite = shoot_malloc_suite_contig(0) => 0x990114
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x1
[Pass] suite->size => 0x1be8000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x990138
[Pass] chunk->signature => 'MemChunk'
[Pass] chunk->size => 0x1be8000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x42114088
[Pass] UNCACHEABLE(p) => 0x42114088
       shoot_free_suite(suite); suite = 0; chunk = 0;
[Pass] suite = shoot_malloc_suite(64*1024*1024) => 0x990114
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x7
[Pass] suite->size => 0x4000000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x990138
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x1be8000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x42114088
[Pass] UNCACHEABLE(p) => 0x42114088
       chunk = GetNextMemoryChunk(suite, chunk) => 0x9901b0
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x1bf4000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x42000064
[Pass] UNCACHEABLE(p) => 0x42000064
       chunk = GetNextMemoryChunk(suite, chunk) => 0x990208
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x20dc000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x5bb140e4
[Pass] UNCACHEABLE(p) => 0x5bb140e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x990280
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x25c4000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x59b140e4
[Pass] UNCACHEABLE(p) => 0x59b140e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x9902f8
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x2aac000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x57b140e4
[Pass] UNCACHEABLE(p) => 0x57b140e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x990370
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x2f94000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x55b140e4
[Pass] UNCACHEABLE(p) => 0x55b140e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x9903e8
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x4000000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x54000064
[Pass] UNCACHEABLE(p) => 0x54000064
       chunk = GetNextMemoryChunk(suite, chunk) => 0x0
[Pass] total => 0x4000000
       shoot_free_suite(suite); suite = 0; chunk = 0;
[Pass] suite = shoot_malloc_suite(0) => 0x990114
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x12
[Pass] suite->size => 0xbf00000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x990138
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x1be8000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x42114088
[Pass] UNCACHEABLE(p) => 0x42114088
       chunk = GetNextMemoryChunk(suite, chunk) => 0x9901b0
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x1bf4000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x42000064
[Pass] UNCACHEABLE(p) => 0x42000064
       chunk = GetNextMemoryChunk(suite, chunk) => 0x990208
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x20dc000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x5bb140e4
[Pass] UNCACHEABLE(p) => 0x5bb140e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x990280
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x25c4000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x59b140e4
[Pass] UNCACHEABLE(p) => 0x59b140e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x9902f8
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x2aac000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x57b140e4
[Pass] UNCACHEABLE(p) => 0x57b140e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x990370
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x2f94000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x55b140e4
[Pass] UNCACHEABLE(p) => 0x55b140e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x9903e8
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x4aa8000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x54000064
[Pass] UNCACHEABLE(p) => 0x54000064
       chunk = GetNextMemoryChunk(suite, chunk) => 0x990460
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x65bc000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x56000064
[Pass] UNCACHEABLE(p) => 0x56000064
       chunk = GetNextMemoryChunk(suite, chunk) => 0x9904d8
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x80d0000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x58000064
[Pass] UNCACHEABLE(p) => 0x58000064
       chunk = GetNextMemoryChunk(suite, chunk) => 0x990550
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x9be4000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x5a000064
[Pass] UNCACHEABLE(p) => 0x5a000064
       chunk = GetNextMemoryChunk(suite, chunk) => 0x9905c8
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0xa0cc000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x53b140e4
[Pass] UNCACHEABLE(p) => 0x53b140e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x990640
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0xa5b4000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x51b140e4
[Pass] UNCACHEABLE(p) => 0x51b140e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x9906b8
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0xaa9c000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4fb140e4
[Pass] UNCACHEABLE(p) => 0x4fb140e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x990730
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0xaf84000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4db140e4
[Pass] UNCACHEABLE(p) => 0x4db140e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x9907a8
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0xb46c000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4bb140e4
[Pass] UNCACHEABLE(p) => 0x4bb140e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x990820
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0xb954000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x49b140e4
[Pass] UNCACHEABLE(p) => 0x49b140e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x990898
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0xbe3c000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x47b140e4
[Pass] UNCACHEABLE(p) => 0x47b140e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x990910
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0xbf00000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x45b140e4
[Pass] UNCACHEABLE(p) => 0x45b140e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x0
[Pass] total => 0xbf00000
       shoot_free_suite(suite); suite = 0; chunk = 0;
[Pass] strlen("abc") => 0x3
[Pass] strlen("qwertyuiop") => 0xa
[Pass] strlen("") => 0x0
[Pass] strcpy(msg, "hi there") => 0x1853ec
[Pass] msg => 'hi there'
[Pass] snprintf(a, sizeof(a), "foo") => 0x3
[Pass] snprintf(b, sizeof(b), "foo") => 0x3
[Pass] strcmp(a, b) => 0x0
[Pass] snprintf(a, sizeof(a), "bar") => 0x3
[Pass] snprintf(b, sizeof(b), "baz") => 0x3
[Pass] strcmp(a, b) => 0xfffffff8
[Pass] snprintf(a, sizeof(a), "Display") => 0x7
[Pass] snprintf(b, sizeof(b), "Defishing") => 0x9
[Pass] strcmp(a, b) => 0x4
[Pass] snprintf(buf, 3, "%d", 1234) => 0x2
[Pass] buf => '12'
[Pass] memcpy(foo, bar, 6) => 0x1853c0
[Pass] foo => 'asdfghuiop'
[Pass] memset(bar, '*', 5) => 0x1853a0
[Pass] bar => '*****hjkl;'
       bzero32(bar + 5, 5)
[Pass] bar => '****'
       EngDrvOut(LCD_Palette[0], 0x1234)
[Pass] shamem_read(LCD_Palette[0]) => 0x1234
       call("TurnOnDisplay")
[Pass] DISPLAY_IS_ON => 0x1
       call("TurnOffDisplay")
[Pass] DISPLAY_IS_ON => 0x0
       call("TurnOnDisplay")
[Pass] DISPLAY_IS_ON => 0x1
       task_create("test", 0x1c, 0x1000, test_task, 0) => 0x57c00aa
[Pass] test_task_created => 0x1
[Pass] get_current_task_name() => 'run_test'
[Pass] task_max => 0x68
[Pass] task_max => 0x68
[Pass] mq = mq ? mq : (void*)msg_queue_create("test", 5) => 0x57e0084
[Pass] msg_queue_post(mq, 0x1234567) => 0x0
[Pass] msg_queue_receive(mq, (struct event **) &m, 500) => 0x0
[Pass] m => 0x1234567
[Pass] msg_queue_receive(mq, (struct event **) &m, 500) => 0x9
[Pass] sem = sem ? sem : create_named_semaphore("test", 1) => 0x5800146
[Pass] take_semaphore(sem, 500) => 0x0
[Pass] take_semaphore(sem, 500) => 0x9
[Pass] give_semaphore(sem) => 0x0
[Pass] take_semaphore(sem, 500) => 0x0
[Pass] give_semaphore(sem) => 0x0
[Pass] rlock = rlock ? rlock : CreateRecursiveLock(0) => 0x582005e
[Pass] AcquireRecursiveLock(rlock, 500) => 0x0
[Pass] AcquireRecursiveLock(rlock, 500) => 0x0
[Pass] ReleaseRecursiveLock(rlock) => 0x0
[Pass] ReleaseRecursiveLock(rlock) => 0x0
[Pass] ReleaseRecursiveLock(rlock) => 0xf
       SetGUIRequestMode(1); msleep(1000);
[Pass] CURRENT_GUI_MODE => 0x1
       SetGUIRequestMode(2); msleep(1000);
[Pass] CURRENT_GUI_MODE => 0x2
       SetGUIRequestMode(0); msleep(1000);
[Pass] CURRENT_GUI_MODE => 0x0
[Pass] display_idle() => 0x1
       GUI_Control(BGMT_PLAY, 0, 0, 0); msleep(1000);
[Pass] PLAY_MODE => 0x1
[Pass] MENU_MODE => 0x0
       GUI_Control(BGMT_MENU, 0, 0, 0); msleep(1000);
[Pass] MENU_MODE => 0x1
[Pass] PLAY_MODE => 0x0
[Pass] dialog->type => 'DIALOG'
       GUI_Control(BGMT_MENU, 0, 0, 0); msleep(500);
[Pass] MENU_MODE => 0x0
[Pass] PLAY_MODE => 0x0
       SW1(1,100)
[Pass] HALFSHUTTER_PRESSED => 0x1
       SW1(0,100)
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] is_play_mode() => 0x1
[Pass] is_pure_play_photo_mode() => 0x1
[Pass] is_pure_play_movie_mode() => 0x0
[Pass] is_play_mode() => 0x1
[Pass] is_pure_play_photo_mode() => 0x0
[Pass] is_pure_play_movie_mode() => 0x0
[Pass] is_play_mode() => 0x1
[FAIL] is_pure_play_photo_mode() => 0x1
[FAIL] is_pure_play_movie_mode() => 0x0
[Pass] is_play_mode() => 0x1
[FAIL] is_pure_play_photo_mode() => 0x1
[Pass] is_pure_play_movie_mode() => 0x0

3 Fails in dm-spy-experiment

12727 passed, 23-24 failed in lua_fix branch (I can't find log on CF). lv_focus_status test fails 2 or 3 times then appears to Pass, some UI_Lock errors in console.

After finishing test camera is locked up in a movie record and I need to remove battery.

I have also an hypothesis of a possible wrong stub regarding drawing on screen, due to be unable in attempt to port flexinfo to 50D. So I tried Redraw Test and nothing is show on screen only blue Led blinks 3 times. What should happen?
Draw rectangle test works.

a1ex

Drawing on the screen is currently done by writing directly to video memory. In all other models, Canon code only redraws when it has something to redraw (with minor exceptions). Not so with 50D - here, Canon code redraws itself over and over (and for some unknown reason, it does not redraw the entire screen, just a very large part of it).

Redraw does not have visible side effects on its own - Canon code is flicker-free when redrawing itself. Try running the rectangle test at the same time.

lv_focus_status will probably fail in LiveView - if it's like 500D, it won't autofocus by pressing half-shutter. Not sure how to fix.

is_pure_play_photo_mode() -> this should return true when reviewing an image in PLAY mode (it's tested from Lua as well). This works by comparing the return value of get_current_dialog_handler() with some predefined stub (PlayMain_handler - Canon dialog function used for reviewing images). To check, print the result of get_current_dialog_handler() somewhere while in PLAY mode, and compare it with the PlayMain_handler stub.


dfort

The Call for testers post is showing that most of the cameras that I own haven't been tested yet. Since I'm a bit stuck on my other projects and short on time to get myself unstuck -- let the testing being.

First up, EOSM.

api_test.lua

===============================================================================
ML/SCRIPTS/API_TEST.LUA - 2018-3-22 14:09:55
===============================================================================

Strict mode tests...
Strict mode tests passed.

Generic tests...
arg = table:
  [0] = "API_TEST.LUA"
camera = table:
  shutter = table:
    raw = 104
    apex = 6.
    ms = 16
    value = 0.015625
  aperture = table:
    raw = 59
    apex = 6.375
    value = 9.100001
    min = table:
      raw = 40
      apex = 4.
      value = 4.
    max = table:
      raw = 80
      apex = 9.
      value = 22.6
  iso = table:
    raw = 101
    apex = 8.625
    value = 1250
  ec = table:
    raw = 0
    value = 0
  flash_ec = table:
    raw = 0
    value = 0
  kelvin = 6500
  mode = 20
  metering_mode = 5
  drive_mode = 0
  model = "Canon EOS M"
  model_short = "EOSM"
  firmware = "2.0.2"
  temperature = 208
  gui = table:
    menu = false
    play = false
    play_photo = false
    play_movie = false
    qr = false
    idle = true
  reboot = function: p
  bulb = function: p
  wait = function: p
  burst = function: p
  shoot = function: p
event = table:
  pre_shoot = nil
  post_shoot = nil
  shoot_task = nil
  seconds_clock = nil
  keypress = nil
  custom_picture_taking = nil
  intervalometer = nil
  config_save = nil
console = table:
  hide = function: p
  write = function: p
  show = function: p
  clear = function: p
lv = table:
  enabled = true
  paused = false
  running = true
  zoom = 1
  overlays = 2
  pause = function: p
  resume = function: p
  stop = function: p
  wait = function: p
  info = function: p
  start = function: p
lens = table:
  name = "EF-M11-22mm f/4-5.6 IS STM"
  focal_length = 11
  focus_distance = 450
  hyperfocal = 721
  dof_near = 287
  dof_far = 1125
  af = false
  af_mode = 3
  autofocus = function: p
  focus = function: p
display = table:
  idle = nil
  height = 480
  width = 720
  clear = function: p
  screenshot = function: p
  print = function: p
  pixel = function: p
  notify_box = function: p
  on = function: p
  off = function: p
  draw = function: p
  load = function: p
  circle = function: p
  rect = function: p
  line = function: p
key = table:
  last = 10
  press = function: p
  wait = function: p
menu = table:
  visible = false
  get = function: p
  select = function: p
  new = function: p
  block = function: p
  set = function: p
  open = function: p
  close = function: p
movie = table:
  recording = false
  stop = function: p
  start = function: p
dryos = table:
  clock = 12
  ms_clock = 12319
  image_prefix = "IMG_"
  dcim_dir = table:
    exists = true
    create = function: p
    children = function: p
    files = function: p
    parent = table:
      exists = true
      create = function: p
      children = function: p
      files = function: p
      parent = table:
        exists = true
        create = function: p
        children = function: p
        files = function: p
        parent = nil
        path = "B:/"
      path = "B:/DCIM/"
    path = "B:/DCIM/100CANON/"
  config_dir = table:
    exists = true
    create = function: p
    children = function: p
    files = function: p
    parent = table:
      exists = true
      create = function: p
      children = function: p
      files = function: p
      parent = table:
        exists = true
        create = function: p
        children = function: p
        files = function: p
        parent = nil
        path = "B:/"
      path = "ML/"
    path = "ML/SETTINGS/"
  ml_card = table:
    cluster_size = 32768
    drive_letter = "B"
    file_number = 6056
    folder_number = 100
    free_space = 31111424
    type = "SD"
    _card_ptr = userdata
    path = "B:/"
  shooting_card = table:
    cluster_size = 32768
    drive_letter = "B"
    file_number = 6056
    folder_number = 100
    free_space = 31111424
    type = "SD"
    _card_ptr = userdata
    path = "B:/"
  date = table:
    yday = 81
    sec = 57
    wday = 5
    day = 22
    year = 2018
    min = 9
    month = 3
    isdst = false
    hour = 14
  directory = function: p
  rename = function: p
  remove = function: p
  call = function: p
interval = table:
  time = 10
  count = 0
  running = false
  stop = function: p
battery = table:
function not available on this camera
stack traceback:
[C]: in ?
[C]: in for iterator 'for iterator'
ML/SCRIPTS/LIB/logger.lua:125: in function 'logger.serialize'
ML/SCRIPTS/API_TEST.LUA:36: in function <ML/SCRIPTS/API_TEST.LUA:35>
[C]: in function 'xpcall'
ML/SCRIPTS/API_TEST.LUA:35: in function 'print_table'
ML/SCRIPTS/API_TEST.LUA:81: in function 'generic_tests'
ML/SCRIPTS/API_TEST.LUA:1338: in function 'api_tests'
ML/SCRIPTS/API_TEST.LUA:1364: in main chunktask = table:
  create = function: p
  yield = function: p
property = table:
Generic tests completed.

Module tests...
Testing file I/O...
Copy test: autoexec.bin -> tmp.bin
Copy test OK
Append test: tmp.txt
Append test OK
Rename test: apple.txt -> banana.txt
Rename test OK
Rename test: apple.txt -> ML/banana.txt
Rename test OK
File I/O tests completed.

Testing Canon GUI functions...
Enter MENU mode...
Enter PLAY mode...
Enter PLAY mode...
Exit PLAY mode...


Doesn't get very far, tried a few times but it keeps getting stuck. No Assert log though the screen indicates that it did a traceback.



selftest.mo -> stubs tests
[Pass] is_play_mode() => 0x1
[INFO] Camera model: Canon EOS M 2.0.2 (0x80000331 EOSM)
[Pass] is_camera("DIGIC", "*") => 0x1
[Pass] is_camera(__camera_model_short, firmware_version) => 0x1
[Pass] src = fio_malloc(size) => 0x4de1a084
[Pass] dst = fio_malloc(size) => 0x4e61e090
[Pass] memcmp(dst, src, 4097) => 0xa2
[Pass] edmac_memcpy(dst, src, 4097) => 0x4e61e090
[Pass] memcmp(dst, src, 4097) => 0x0
[Pass] edmac_memcpy(dst, src, 4097) => 0x4e61e090
[Pass] memcmp(dst, src, size) => 0x31
[Pass] edmac_memcpy(dst, src, size) => 0x4e61e090
[Pass] memcmp(dst, src, size) => 0x0
[Pass] memcmp(dst, src, size) => 0xffffffa6
[Pass] edmac_memcpy_start(dst, src, size) => 0x4e61e090
       dt => 0x2975
[Pass] copied => 0x4005f0
[Pass] copied => 0x4005f0
[Pass] copied => 0x4005f0
[Pass] memcmp(dst, src, copied) => 0x0
[Pass] memcmp(dst, src, copied + 16) => 0x61
       edmac_memcpy_finish()
       free(src)
       free(dst)
Cache test A (EDMAC on BMP buffer)...
[Pass] bmp = bmp_load("ML/CROPMKS/CINESCO2.BMP", 1) => 0x806b18
[Pass] old => 0x0
[Pass] irq => 0xc0
[Pass] differences => 0x18d0
[Pass] old => 0x0
[Pass] irq => 0xc0
[Pass] differences => 0x0
Cache test B (FIO on 8K buffer)...
[Pass] tries[0] => 0x107
[Pass] tries[1] => 0xf4
[Pass] tries[2] => 0x107
[Pass] tries[3] => 0xe6
[Pass] failr[0] => 0x84
[Pass] failw[0] => 0xf7
[Pass] failr[1] => 0x67
[Pass] failw[1] => 0x0
[Pass] failr[2] => 0x0
[Pass] failw[2] => 0xeb
[Pass] failr[3] => 0x0
[Pass] failw[3] => 0x0
       times[0] / tries[0] => 0x1a
       times[1] / tries[1] => 0x1b
       times[2] / tries[2] => 0x1b
       times[3] / tries[3] => 0x1b
Cache tests finished.

[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x1
[FAIL] wait_focus_status(1000, 3) => 0x0
[FAIL] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x1
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x1
[FAIL] wait_focus_status(1000, 3) => 0x0
[FAIL] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x1
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x1
[FAIL] wait_focus_status(1000, 3) => 0x0
[FAIL] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x1
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x1
[FAIL] wait_focus_status(1000, 3) => 0x0
[FAIL] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x1
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x1
[FAIL] wait_focus_status(1000, 3) => 0x0
[FAIL] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x1
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x1
[FAIL] wait_focus_status(1000, 3) => 0x0
[FAIL] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x1
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x1
[FAIL] wait_focus_status(1000, 3) => 0x0
[FAIL] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x1
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x1
[FAIL] wait_focus_status(1000, 3) => 0x0
[FAIL] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x1
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x1
[FAIL] wait_focus_status(1000, 3) => 0x0
[FAIL] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x1
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x1
[FAIL] wait_focus_status(1000, 3) => 0x0
[FAIL] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] lv_focus_status => 0x1
[Pass] HALFSHUTTER_PRESSED => 0x1
[Pass] wait_focus_status(1000, 3) => 0x0
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] lv_focus_status => 0x1
[Pass] f = FIO_CreateFile("test.dat") => 0x3
[Pass] FIO_WriteFile(f, (void*)0xFF000000, 0x10000) => 0x10000
[Pass] FIO_WriteFile(f, (void*)0xFF000000, 0x10000) => 0x10000
       FIO_CloseFile(f)
[Pass] FIO_GetFileSize("test.dat", &size) => 0x0
[Pass] size => 0x20000
[Pass] p = (void*)_alloc_dma_memory(0x20000) => 0x4085b300
[Pass] f = FIO_OpenFile("test.dat", O_RDONLY | O_SYNC) => 0x3
[Pass] FIO_ReadFile(f, p, 0x20000) => 0x20000
       FIO_CloseFile(f)
       _free_dma_memory(p)
[Pass] count => 0x3a98
[Pass] buf = fio_malloc(0x1000000) => 0x4de1a084
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000000
[Pass] f = FIO_OpenFile("test.dat", O_RDWR | O_SYNC) => 0x3
[Pass] FIO_SeekSkipFile(f, 0, SEEK_END) => 0x82000000
[Pass] FIO_WriteFile(f, buf, 0x10) => 0x10
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_END) => 0x81fffff0
[Pass] FIO_WriteFile(f, buf, 0x30) => 0x30
[Pass] FIO_SeekSkipFile(f, 0x20, SEEK_SET) => 0x20
[Pass] FIO_SeekSkipFile(f, 0x30, SEEK_CUR) => 0x50
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_CUR) => 0x30
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000020
[Pass] is_file("test.dat") => 0x1
[Pass] FIO_RemoveFile("test.dat") => 0x0
[Pass] is_file("test.dat") => 0x0
[Pass] SetTimerAfter(0, timer_cbr, overrun_cbr, 0) => 0x15
[Pass] timer_func => 0x2
[Pass] SetTimerAfter(1000, timer_cbr, overrun_cbr, 0) => 0xcb30
       msleep(900)
[Pass] timer_func => 0x0
       msleep(200)
[Pass] timer_func => 0x1
[Pass] ABS((timer_time/1000 - t0) - 1000) => 0x1
[Pass] ABS((timer_arg - ta0) - 1000) => 0xa
[Pass] timer = SetTimerAfter(1000, timer_cbr, overrun_cbr, 0) => 0xcb9e
       msleep(400)
       CancelTimer(timer)
[Pass] timer_func => 0x0
       msleep(1500)
[Pass] timer_func => 0x0
[Pass] SetHPTimerAfterNow(0, timer_cbr, overrun_cbr, 0) => 0x15
[Pass] timer_func => 0x2
[Pass] SetHPTimerAfterNow(100000, timer_cbr, overrun_cbr, 0) => 0x32c02
       msleep(90)
[Pass] timer_func => 0x0
       msleep(20)
[Pass] timer_func => 0x1
[Pass] ABS(DeltaT(timer_time, t0) - 100000) => 0x118
[Pass] ABS(DeltaT(timer_arg, ta0) - 100000) => 0xf9
[Pass] ABS((get_us_clock() - t0) - 110000) => 0x372
[Pass] SetHPTimerAfterNow(90000, next_tick_cbr, overrun_cbr, 0) => 0x32c04
       msleep(80)
[Pass] timer_func => 0x0
       msleep(20)
[Pass] timer_func => 0x3
       msleep(80)
[Pass] timer_func => 0x3
       msleep(20)
[Pass] timer_func => 0x1
[Pass] ABS(DeltaT(timer_time, t0) - 300000) => 0x3ff
[Pass] ABS(DeltaT(timer_arg, ta0) - 300000) => 0x3e5
[Pass] ABS((get_us_clock() - t0) - 310000) => 0x224
       t0 = GET_DIGIC_TIMER() => 0xee0b2
       msleep(250)
       t1 = GET_DIGIC_TIMER() => 0x2a6bd
[Pass] ABS(MOD(t1-t0, 1048576)/1000 - 250) => 0x3
       LoadCalendarFromRTC( &now )
       s0 = now.tm_sec => 0x5
       Date/time: 2018/03/22 14:18:05
       msleep(1500)
       LoadCalendarFromRTC( &now )
       s1 = now.tm_sec => 0x7
[Pass] MOD(s1-s0, 60) => 0x2
[Pass] MOD(s1-s0, 60) => 0x2
       m0 = MALLOC_FREE_MEMORY => 0x3e720
[Pass] p = (void*)_malloc(50*1024) => 0x131168
[Pass] CACHEABLE(p) => 0x131168
       m1 = MALLOC_FREE_MEMORY => 0x31f10
       _free(p)
       m2 = MALLOC_FREE_MEMORY => 0x3e720
[Pass] ABS((m0-m1) - 50*1024) => 0x10
[Pass] ABS(m0-m2) => 0x0
       m0 = GetFreeMemForAllocateMemory() => 0x33f248
[Pass] p = (void*)_AllocateMemory(128*1024) => 0x85b2c0
[Pass] CACHEABLE(p) => 0x85b2c0
       m1 = GetFreeMemForAllocateMemory() => 0x31f23c
       _FreeMemory(p)
       m2 = GetFreeMemForAllocateMemory() => 0x33f248
[Pass] ABS((m0-m1) - 128*1024) => 0xc
[Pass] ABS(m0-m2) => 0x0
       m01 = MALLOC_FREE_MEMORY => 0x3e720
       m02 = GetFreeMemForAllocateMemory() => 0x33f248
[Pass] p = (void*)_alloc_dma_memory(128*1024) => 0x4085b300
[Pass] UNCACHEABLE(p) => 0x4085b300
[Pass] CACHEABLE(p) => 0x85b300
[Pass] UNCACHEABLE(CACHEABLE(p)) => 0x4085b300
       _free_dma_memory(p)
[Pass] p = (void*)_shoot_malloc(16*1024*1024) => 0x4de1a074
[Pass] UNCACHEABLE(p) => 0x4de1a074
       _shoot_free(p)
       m11 = MALLOC_FREE_MEMORY => 0x3e720
       m12 = GetFreeMemForAllocateMemory() => 0x33f248
[Pass] ABS(m01-m11) => 0x0
[Pass] ABS(m02-m12) => 0x0
[Pass] suite = shoot_malloc_suite_contig(16*1024*1024) => 0x11d6e8
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x1
[Pass] suite->size => 0x1000000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x12a948
[Pass] chunk->signature => 'MemChunk'
[Pass] chunk->size => 0x1000000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4de1a070
[Pass] UNCACHEABLE(p) => 0x4de1a070
       shoot_free_suite(suite); suite = 0; chunk = 0;
[Pass] suite = shoot_malloc_suite_contig(0) => 0x11d6e8
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x1
[Pass] suite->size => 0x12b4000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x12a948
[Pass] chunk->signature => 'MemChunk'
[Pass] chunk->size => 0x12b4000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4de1a070
[Pass] UNCACHEABLE(p) => 0x4de1a070
       largest_shoot_block = suite->size => 0x12b4000
[INFO] largest_shoot_block: 19MB
       shoot_free_suite(suite); suite = 0; chunk = 0;
[Pass] suite = shoot_malloc_suite(largest_shoot_block + 1024*1024) => 0x11d6e8
[Pass] suite->signature => 'MemSuite'
[FAIL] suite->num_chunks => 0x1
[Pass] suite->size => 0x13b4000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x12a948
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x13b4000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4de1a070
[Pass] UNCACHEABLE(p) => 0x4de1a070
       chunk = GetNextMemoryChunk(suite, chunk) => 0x0
[Pass] total => 0x13b4000
       shoot_free_suite(suite); suite = 0; chunk = 0;
[Pass] suite = shoot_malloc_suite(0) => 0x11d6e8
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x3
[Pass] suite->size => 0x1700000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x12a948
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x13b4000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4de1a070
[Pass] UNCACHEABLE(p) => 0x4de1a070
       chunk = GetNextMemoryChunk(suite, chunk) => 0x131168
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x149c000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4ae00064
[Pass] UNCACHEABLE(p) => 0x4ae00064
       chunk = GetNextMemoryChunk(suite, chunk) => 0x1311a0
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x1700000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x419ff0a4
[Pass] UNCACHEABLE(p) => 0x419ff0a4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x0
[Pass] total => 0x1700000
       shoot_free_suite(suite); suite = 0; chunk = 0;
[FAIL] suite->num_chunks => 0x1
[FAIL] suite->num_chunks => 0x1
[FAIL] suite->num_chunks => 0x1
[FAIL] suite->num_chunks => 0x1
[FAIL] suite->num_chunks => 0x1
[FAIL] suite->num_chunks => 0x1
[FAIL] suite->num_chunks => 0x1
[FAIL] suite->num_chunks => 0x1
[FAIL] suite->num_chunks => 0x1
[FAIL] suite->num_chunks => 0x1
[FAIL] suite->num_chunks => 0x1
[FAIL] suite->num_chunks => 0x1
[FAIL] suite->num_chunks => 0x1
[FAIL] suite->num_chunks => 0x1
[FAIL] suite->num_chunks => 0x1
[FAIL] suite->num_chunks => 0x1
[FAIL] suite->num_chunks => 0x1
[FAIL] suite->num_chunks => 0x1
[FAIL] suite->num_chunks => 0x1
[Pass] strlen("abc") => 0x3
[Pass] strlen("qwertyuiop") => 0xa
[Pass] strlen("") => 0x0
[Pass] strcpy(msg, "hi there") => 0x213d2c
[Pass] msg => 'hi there'
[Pass] snprintf(a, sizeof(a), "foo") => 0x3
[Pass] snprintf(b, sizeof(b), "foo") => 0x3
[Pass] strcmp(a, b) => 0x0
[Pass] snprintf(a, sizeof(a), "bar") => 0x3
[Pass] snprintf(b, sizeof(b), "baz") => 0x3
[Pass] strcmp(a, b) => 0xfffffff8
[Pass] snprintf(a, sizeof(a), "Display") => 0x7
[Pass] snprintf(b, sizeof(b), "Defishing") => 0x9
[Pass] strcmp(a, b) => 0x4
[Pass] snprintf(buf, 3, "%d", 1234) => 0x2
[Pass] buf => '12'
[Pass] memcpy(foo, bar, 6) => 0x213d00
[Pass] foo => 'asdfghuiop'
[Pass] memset(bar, '*', 5) => 0x213ce0
[Pass] bar => '*****hjkl;'
       bzero32(bar + 5, 5)
[Pass] bar => '****'
       EngDrvOut(LCD_Palette[0], 0x1234)
[Pass] shamem_read(LCD_Palette[0]) => 0x1234
       call("TurnOnDisplay")
[Pass] DISPLAY_IS_ON => 0x1
       call("TurnOffDisplay")
[Pass] DISPLAY_IS_ON => 0x0
       call("TurnOnDisplay")
[Pass] DISPLAY_IS_ON => 0x1
       task_create("test", 0x1c, 0x1000, test_task, 0) => 0xed0a00b0
[Pass] test_task_created => 0x1
[Pass] get_current_task_name() => 'run_test'
[Pass] get_task_name_from_id(current_task->taskId) => 'run_test'
[Pass] task_max => 0x68
[Pass] task_max => 0x68
[Pass] mq = mq ? mq : (void*)msg_queue_create("test", 5) => 0xed0c00b6
[Pass] msg_queue_post(mq, 0x1234567) => 0x0
[Pass] msg_queue_receive(mq, (struct event **) &m, 500) => 0x0
[Pass] m => 0x1234567
[Pass] msg_queue_receive(mq, (struct event **) &m, 500) => 0x9
[Pass] sem = sem ? sem : create_named_semaphore("test", 1) => 0xed0e0200
[Pass] take_semaphore(sem, 500) => 0x0
[Pass] take_semaphore(sem, 500) => 0x9
[Pass] give_semaphore(sem) => 0x0
[Pass] take_semaphore(sem, 500) => 0x0
[Pass] give_semaphore(sem) => 0x0
[Pass] rlock = rlock ? rlock : CreateRecursiveLock(0) => 0xed100066
[Pass] AcquireRecursiveLock(rlock, 500) => 0x0
[Pass] AcquireRecursiveLock(rlock, 500) => 0x0
[Pass] ReleaseRecursiveLock(rlock) => 0x0
[Pass] ReleaseRecursiveLock(rlock) => 0x0
[Pass] ReleaseRecursiveLock(rlock) => 0xf
       SetGUIRequestMode(1); msleep(1000);
[Pass] CURRENT_GUI_MODE => 0x1
       SetGUIRequestMode(2); msleep(1000);
[Pass] CURRENT_GUI_MODE => 0x2
       SetGUIRequestMode(0); msleep(1000);
[Pass] CURRENT_GUI_MODE => 0x0
[Pass] display_idle() => 0x1
       GUI_Control(BGMT_PLAY, 0, 0, 0); msleep(1000);
[Pass] PLAY_MODE => 0x1
[Pass] MENU_MODE => 0x0
       GUI_Control(BGMT_MENU, 0, 0, 0); msleep(1000);
[Pass] MENU_MODE => 0x1
[Pass] PLAY_MODE => 0x0
[Pass] dialog->type => 'DIALOG'
       GUI_Control(BGMT_MENU, 0, 0, 0); msleep(500);
[Pass] MENU_MODE => 0x0
[Pass] PLAY_MODE => 0x0
       SW1(1,100)
[Pass] HALFSHUTTER_PRESSED => 0x1
       SW1(0,100)
[Pass] HALFSHUTTER_PRESSED => 0x0
[Pass] is_play_mode() => 0x1
[FAIL] is_pure_play_photo_mode() => 0x0
[Pass] is_pure_play_movie_mode() => 0x0
[Pass] is_play_mode() => 0x1
[Pass] is_pure_play_photo_mode() => 0x0
[Pass] is_pure_play_movie_mode() => 0x0
[Pass] is_play_mode() => 0x1
[Pass] is_pure_play_photo_mode() => 0x0
[Pass] is_pure_play_movie_mode() => 0x1
[Pass] is_play_mode() => 0x1
[Pass] is_pure_play_photo_mode() => 0x0
[Pass] is_pure_play_movie_mode() => 0x0
=========================================================
Test complete, 11351 passed, 41 failed.
.


Got through it but had 41 failed tests. The EOSM2 that still has a long way to go before it is even ready for testing fared about the same on this.

bench.mo -> memory benchmarks


Ok--I doubt this is what the BENCH0.PPM file should look like. Maybe it is the CONFIG_MENU_TIMEOUT_FIX clearing out the screen every few seconds that is doing this?