6D/M/100D/70D: In Live View mode, ML Menu times out after 5-10s

Issue #1974 new
Anonymous created an issue

There are multiple reports about this in the forums (see below). Basically, when in Live View mode, if the ML Menu is accessed (via the trash button), it times out and goes back to the Canon Live View screen after typically 5-10 seconds. The amount of time it takes to go back varies.

Nanomad on the forums says that "The underlying Canon dialog times out." I think this is right -- I have noticed that when the ML Menu disappears, for a very brief period (maybe 1/10 of a second) a Canon-looking dialog appears but then the regular Live View mode is shown immediately thereafter.

http://www.magiclantern.fm/forum/index.php?topic=10939.msg106042#msg106042 http://www.magiclantern.fm/forum/index.php?topic=8104.msg73551#msg73551 http://www.magiclantern.fm/forum/index.php?topic=11445.msg111510#msg111510 http://www.magiclantern.fm/forum/index.php?topic=11072.msg107928#msg107928 http://www.magiclantern.fm/forum/index.php?topic=10393.msg100514#msg100514

Comments (121)

  1. Evan Mezeske

    Oh, I forgot to mention that I have not seen this problem when in non-live-view mode. So the workaround is to switch the camera to viewfinder mode, enter the ML Menu, make your changes, exit the ML menu, and switch back to ML mode. Not very convenient, but better than nothing.

  2. Alex

    I think there are two possible solutions:

    • find the timer that causes Canon's dialog to timeout, and cancel it
    • send dummy button clicks (with fake_simple_button) every few seconds, to trick Canon code and reset the timer

    For 1, one has to do some reverse engineering, see https://bitbucket.org/hudson/magic-lantern/commits/a7dc5d47796fa6a473313d5cdd40f47b1c005e21 and https://bitbucket.org/hudson/magic-lantern/pull-request/480/prevent-date-time-from-flickering-while-ml

    For 2, no low-level research is required, just somebody willing to check how these dialogs react to fake events.

    Something like this in don't click me:

    while(1)
    {
        fake_simple_button(BGMT_UNPRESS_UDLR);
        msleep(1000);
    }
    

    Extra care must be taken to make sure the fake buttons don't do any action in the menu (either find a button code that does nothing in menu, or block the fake event in handle_ml_menu_keys).

  3. Ed Halley

    Just confirming I see this same issue. I have to switch away from LiveView (including movie mode) to make any changes to movie capture ML settings. Since all the movie capture settings appear dim/disabled when not in movie mode, it can be hard to see the settings in bright environments.

  4. Jarno Paananen

    In case this is related to EOS M menu disappearing after a few seconds as well, I tried number 2 of a1ex's suggestions. I tried a few button codes (EOS M doesn't have that many buttons to begin with) and with all of them the menu still disappeared like before. Even when I used button left for example, which made the ML menu move between tabs, the menu still closed. If I browse the menus normally with physical buttons it doesn't close so there seems to be something different between those and faking them.

  5. Alex

    If faking the left button causes ML menu to move between tabs, the event does not reach Canon GUI code. Can you comment out the "case BGMT_PRESS_LEFT" from handle_ml_menu_keys (menu.c) and try the same test?

    To make sure the event reaches Canon code (and is not trapped by some ML feature), you can print it in gui.c, at the very end, right before calling f(event); that "f" is Canon's event handler.

  6. Jarno Paananen

    Tried both BGMT_PRESS_LEFT and BGMT_UNPRESS_LEFT and unfortunately neither help. The event goes to Canon code and moves the AF square over ML menu, but the menu still disappears as before.

  7. Jarno Paananen

    Thanks, that seems quite handy tool! I think I got pretty good, even if a bit verbose, log out of it, put it in https://www.dropbox.com/s/is79w3pponeb5ii/DM.zip

    I put this small snippet to run_test() and set FPS override to 1 fps so that it started the log when I was back in ML menu and stopped a short while after Canon code closed it.

        msleep(2000);
        debug_intercept(); /* setup the logging code */
        msleep(10000);
        debug_intercept();  /* save the log */
        return;
    

    Anything I should be looking for in the log?

  8. One Percent

    I tried killing dialog timers, blink timer/olc timer and a bunch of others just like the date timer trick. None of them would prevent the menu from disappearing. I found a value that changes when the dialog goes away and altering it only left the dialog up frozen with no scroll wheels. Its like there is an MPU timeout or something.

  9. Alex

    Thanks; I asked because @nikfreak also wanted to look at it on 6D.

    I can't tell much from the log though (only that SetGUIRequestMode call - done by ML - is done right after the underlying dialog was closed). Maybe printing the messages in real-time would help, but that's quite hard because there are a lot of them...

  10. nikfreak

    @Alex, just out of curiosity: do you think if redoing the logs with the latest changes can achieve some better logs as provided logs by Jarno are 2 months old? Like compiling unified and applying the dm-spy-extra stuff into it before compiling? Had a look in unified but can't find dm-spy-extra.c in it. Only dm-spy.c/h. Would it be like copying it from dm-spy-experiments branch to my local unified dir and afterwards enableing something in makefile and afterwards compile? Can you give me a hint how I could achieve this if I want to compile latest unified with dm-spy-experiments. Could need this stuff for future work....

  11. nikfreak

    Hmmmm seen some Stub correction for EOS-M today so browsed through 6D one's, too. Does

    /** Dialog API **/
    NSTUB(0xFF4B4E74,  dialog_redraw)
    

    have any effect on this? Dunno if it's used somewhere in code and could be relevant for this bug. If so then I think above listed stub is wrong.

    I assume it is either 0xFF4B59D8 or FF4B5A3C-RAM_OFFSET or FF4B5A98. Can anyone check???

  12. Alex

    This one is used for asking Canon graphics to redraw. If it's incorrect, it should be really obvious (try commenting it out in zebra.c).

    There is a stress test for it in the Debug menu (Redraw test).

  13. nikfreak

    I did check the stubs from 5D ROM before commenting here yesterday. Did it the same way I found the other handful stubs for 6D with comparing 5D ROM in ARMu. I did some other test yesterday and used my guessed stubs posted above to compile autoexec.bin for 6D. I couldn't see any changing effect of this stub on my 6D whichever of the above stubs I use. So to sum it up: Whatever value I use for this stub nothing changes compared to nightlies. Gave up on this to play around with 32MB card benchmark buffer afterwards.

  14. Alex

    Here's an easy way to see it: run both the rectangle test and the redraw test in parallel at the same time. Start the rectangle test first, to see the difference. When you run both, the rectangles will be erased quickly by the redraws.

    If you don't run the rectangle test, make sure you have some ML overlays on. After the LED blinks, these should flicker like crazy.

  15. nikfreak

    If I remove if-clause in src/gui.c but keep "TASK_OVERRIDE( gui_main_task, ml_gui_main_task);" and recompile then nothing changes on 6D - wether being in Photo mode or LV. Works like before. Obsolete?:

    #ifndef CONFIG_6D
    TASK_OVERRIDE( gui_main_task, ml_gui_main_task);
    #endif
    

    In boot-hack.c all those if-clauses for 6D are confusing. Hijacking 6D gui-task? Is there no possibility to remove that? Another idea may be to re-initiate the 6d gui_task when switching between photo and LV mode to get the bug fixed.

  16. Alex

    I'd also like to fix the task override on 6D, but Canon changed their internal task structure. They also did that on 100D, and probably on 70D. Luckily, QEMU can emulate the DryOS task scheduler, so it's the tool to use in order to fix this. Not an easy job though.

    Another thing to try: Canon calls these things every time they receive an event from the MPU (including button codes):

    call("DisablePowerSave") call("EnablePowerSave")

    And the last idea is to trace the MPU events from SIO3_ISR, figure out how they are translated into GUI events (it probably starts in SwitchFromPartner, not 100% sure), and see what else is called in this process (it must reset some timer somewhere, I guess).

    Will post some findings about MPU communication soon.

  17. nikfreak

    Anonymous Bug Creator writes:

    "Nanomad on the forums says that "The underlying Canon dialog times out." I think this is right -- I have noticed that when the ML Menu disappears, for a very brief period (maybe 1/10 of a second) a Canon-looking dialog appears but then the regular Live View mode is shown immediately thereafter."

    I narrowed it down. It's the "Image Quality" Canon menu (where you select RAW / MRAW... / JPEG L / M / S1...) which is visible for some milliseconds. No matter which canon menu I use before. It's always that image quality menu which is underlying. Additionally and that's a lil bit strange: normally this canon menu has red marker boxes but the underlying one seems to have orange color.

    maybe this description is useful to fix the problem. Anyone an idea?

  18. Alex

    I guess all transparent LV dialogs have the same timeout value, right?

    The mystery is where this timer gets set up - if we knew the timer address, we could simply cancel it.

  19. nikfreak

    Yes, each have the same timeout value. It's about 3-5 sec. Will have to play around with dmspy and add some code to "don't click me". maybe that can help to identify what's happening.

  20. Alex

    Good point. Logging timer functions may help (it's most likely a plain timer, not a high-res one, so logging SetTimerAfter might be useful).

  21. nikfreak

    ok @Alex I have repeatedly stuff like this:

     CtrlSrv:ff52be84:83:01: StartDialogRefreshTimer
       CtrlSrv:00c68888:00:00: *** SetTimerAfter(0x32, 0xff52be34, 0xff52be34, 0x0), from ff52be98
    **INTERRUP:00c68888:00:00: *** TryPostEvent(&"TaskClass", 0x74adc0, 0x3, 0x0, 0x0), from 13b68
    **INTERRUP:00023680:9b:01: eppDeliverInterruptCBR[0]
    **INTERRUP:00c68888:00:00: *** TryPostEvent(&"TaskClass", 0x7336fc, 0x11, 0x0, 0x0), from ff172ba8
    **INTERRUP:00c68888:00:00: *** TryPostEvent(&"TaskClass", 0x75b8c0, 0x9, 0x0, 0x0), from ff24b078
    

    especially the first 2 lines can be seen in the log together while the other following ones don't pop up always but still often... Could only paste some kbs to pastebin:

    http://pastebin.com/YescVNTZ

  22. nikfreak

    Ok I found some GUI mode changes like this:

    PropMgr:ff0cc964:89:03: GUI_STATE : IDLE (SW = 1, JOB = 0)
       PropMgr:ff0dfb44:85:03: GUI_ChangeMode:0
       PropMgr:ff0df994:85:03: GUI_Control:55 0x0
       PropMgr:00c68824:00:00: *** TryPostEvent(&"TaskClass", &"PropMgr", 0x5, 0xa5d5f0, 0x80020000), from ff130844
       PropMgr:ff30d23c:01:03: Deliv WaitID = 0x80020000, 0xFF0CCC5C(9)
       PropMgr:00c68824:00:00: *** TryPostEvent(&"TaskClass", &"PropMgr", 0x5, 0xae76dc, 0x80020000), from ff130844
       PropMgr:ff30d23c:01:03: Deliv WaitID = 0x80020000, 0x00C3F650(10)
       PropMgr:ff1120a0:33:01: SendPipeEvent [0][0][18]
       PropMgr:ff109044:42:01: Com_MgrSendEvent [0][0][44]
       PropMgr:ff1a9b2c:83:01: changeCBR PropID(0x8000000b)Parameter(0)Size(2)
       PropMgr:ff3104fc:01:03: Complete WaitID = 0x80020000, 0xFF0EEF38(9)
       PropMgr:ff3104fc:01:03: Complete WaitID = 0x80020000, 0xFF153634(8)
       PropMgr:ff3104fc:01:03: Complete WaitID = 0x80020000, 0xFF109C30(7)
       PropMgr:ff3104fc:01:03: Complete WaitID = 0x80020000, 0xFF26F3E4(6)
       PropMgr:ff3104fc:01:03: Complete WaitID = 0x80020000, 0xFF11210C(5)
       PropMgr:ff3104fc:01:03: Complete WaitID = 0x80020000, 0xFF297498(4)
       PropMgr:ff3104fc:01:03: Complete WaitID = 0x80020000, 0xFF437374(3)
       PropMgr:ff3104fc:01:03: Complete WaitID = 0x80020000, 0xFF0CCC5C(2)
       PropMgr:ff3104fc:01:03: Complete WaitID = 0x80020000, 0x00C3F650(1)
           Gmt:ff1749dc:9a:02: gmtProperty ID=0x80020000(0x0)
           Gmt:ff177188:9a:02: PROP_GUI_STATE :0
           Gmt:00c68824:00:00: *** TryPostEvent(&"TaskClass", &"PropMgr", 0x5, 0x747e04, 0x80020000), from ff130844
           Gmt:ff0dde30:9a:01: Event 19 Result State 6->6 ID 0x80020000(0) 
       PropMgr:ff3104fc:01:03: Complete WaitID = 0x80020000, 0xFF1780F0(0)
       PropMgr:ff146a60:00:01: [PM] DisablePowerSave (Counter = 5)
       PropMgr:ff146ad0:00:01: [PM] EnablePowerSave (Counter = 4)
    **INTERRUP:ff146a60:00:01: [PM] DisablePowerSave (Counter = 5)
    **INTERRUP:ff146ad0:00:01: [PM] EnablePowerSave (Counter = 4)
    GuiMainTas:ff0dfd1c:84:01: GUI_CONTROL:17
    GuiMainTas:00c68824:00:00: *** CancelTimer(0x17, 0x60000013, 0x1, &"ifyCBR(NOTIFY_PRINTER_CONNECT)"), from ff1aa014
    GuiMainTas:ff1ac128:84:01: gui control end
    GuiMainTas:ff1ac148:84:01: 0msec = 30450 - 30450
    GuiMainTas:ff1ac164:84:01: 140msec = 92165 - 92305
    GuiMainTas:ff0dfd1c:84:01: GUI_CONTROL:15
    GuiMainTas:00c68824:00:00: *** CancelTimer(0x17, 0x60000013, 0x1, 0x1d62fc), from ff1aa014
    GuiMainTas:ff1ac128:84:01: gui control end
    GuiMainTas:ff1ac148:84:01: 0msec = 30450 - 30450
    GuiMainTas:ff1ac164:84:01: 129msec = 92498 - 92627
    GuiMainTas:ff0dfe20:84:01: GUI_CHANGE_MODE:0
    GuiMainTas:ff1ac2a8:84:03: GUI_ChangeMode_Post:0, 0, 8
    GuiMainTas:ff0dfd1c:84:01: GUI_CONTROL:55
    GuiMainTas:00c68824:00:00: *** CancelTimer(0x17, 0x60000013, 0x0, &" Not exist"), from ff1aa014
    GuiMainTas:ff1ac128:84:01: gui control end
    GuiMainTas:ff1ac148:84:01: 0msec = 30460 - 30460
    GuiMainTas:ff1ac164:84:01: 128msec = 93005 - 93133
    **INTERRUP:00c68824:00:00: *** TryPostEvent(&"TaskClass", 0x74ab54, 0x3, 0x0, 0x0), from 13b68
    

    A more detailed log is here: http://pastebin.com/AVkv8ksY

    The full log about 4.33MB is here: http://www.file-upload.net/download-9704590/dm.log.html Hope that helps to find a solution.

  23. nikfreak

    as 70D suffers from same problem in movie and LV I now found out that it won't happen while recording. Doesn't matter if raw_rec used or not. The bug won*t happen.

    Interestingly the menu background will be transparent (kind of very light grey, you can see trough it) while recording (not black). Can't remember if it was transparent when I used to have a 6D. Also took a screenshot from menu but that ppm will have the screen black and not transparent although it appears transparent on LCD. Now tried to catch a log while recording and pressing trash button like crazy (about 20 times to bring the menu on and off.

    Once recording is stopped the bug appears again. menu background is black again. Reproducable whenever I want - also after cold boot.

    Full Log as described

  24. Paul Leavitt

    I'm new to bitbucket (but I've been using ML for 2+ years), I have this same issue on my 6D 1.1.3. Is there a way to upvote bugs or just add my voice to the crowd? I tried disabling all the timers I could think of in the canon menus, image review, power off, etc. Didn't change anything.

  25. Maqs

    You can vote for the bug, but it won't help fixing it. It's just really hard to fix and requires a lot of time and a good understanding of the inner workings of the Canon firmware. There could be workarounds I'm looking into, but I cannot promise anything.

  26. Alex

    PROP_LV_ACTION is used to turn LiveView on or off (see PauseLiveView/ResumeLiveView).

    I believe we should cancel some timer, but I have no idea how to find it. I have some hopes with QEMU though.

  27. Daniel Fort

    I've been doing some testing on a 700D and noticed that it isn't an issue with this camera. I've also been testing the 100D and it does have this issue.

    Please edit the description, removing 700D and adding 100D.

  28. David Milligan

    FYI, I have an EOS M now.

    So what's wrong with just restarting the Canon dialog? There's actually already code to do this that is commented out (with a macro, not comments). That current code causes the screen to blink, but if you take out the bmp_off() and start_redraw_flood(), then it works just fine. Every once and a while the red scroll wheel icon blinks (I assume this is during the time between when the Canon dialog times out and the new one gets started), but the M's scroll wheel is sort of useless anyway, so I wouldn't mind not using it at all in the menu (so maybe we could eliminate the need for the Canon dialog altogether?). Anyway, I couldn't manage to change Canon settings "accidentally" with the scroll wheel by constantly turning the wheel during this time between when the dialog times out and when a new one is started - that doesn't mean it's not possible if you are more lucky than me, or try longer.

  29. Licaon Kter

    You mean in src/menu.c at line 4045?

    --
    ./src/menu.c-4041-                // don't try more often than once per second
    ./src/menu.c-4042-                static int aux = 0;
    ./src/menu.c-4043-                if (should_run_polling_action(1000, &aux))
    ./src/menu.c-4044-                {
    ./src/menu.c-4045-                    bmp_off();
    ./src/menu.c:4046:                    start_redraw_flood();
    ./src/menu.c-4047-                    SetGUIRequestMode(GUIMODE_ML_MENU);
    ./src/menu.c-4048-                }
    ./src/menu.c-4049-                #endif
    ./src/menu.c-4050-            }
    ./src/menu.c-4051-            else
    --
    

    If so, I just tried it and it still timeouts in about 6 seconds. :(

  30. David Milligan

    Theoretically, I guess, wheel events could "get through" to Canon firmware and change shooting settings (see the red wheel warning pop up?). I couldn't manage to do it though when I tried. There might be other reasons I'm not aware of which is why I'm asking.

  31. Alex

    Well, none of my cameras time out in LiveView, so you tell me which variant is more usable :P

    And, indeed, if the scroll wheel is not useful, you could try defining GUIMODE_ML_MENU as 0 in consts.h, so it won't use a dialog. This one will probably apply only to EOS M.

  32. Licaon Kter

    So there are some question marks here:

    ./platform/700D.114/consts.h:157: #define GUIMODE_ML_MENU (RECORDING ? 0 : lv ? 90 : 2) // any from 88...98 ?!
    
    ./platform/70D.111A&B/consts.h:206: #define GUIMODE_ML_MENU (RECORDING ? 0 : lv ? 92 : 2) // any from 88...98 ?!
    
    ./platform/6D.116/consts.h:143: #define GUIMODE_ML_MENU (RECORDING ? 0 : lv ? 92 : 2) // any from 90...102 ?! find one that works (trial/error)
    
    ./platform/EOSM.202/consts.h:105: //~ #define GUIMODE_ML_MENU (recording ? 0 : lv ? 90 : 2) // any from 90...102 ?!
    ./platform/EOSM.202/consts.h:107:#define GUIMODE_ML_MENU ( RECORDING_H264 ?  99 : 90 ) // any from 90...102 ?!
    
    ./platform/100D.100A&B&C/consts.h:105: #define GUIMODE_ML_MENU (RECORDING ? 0 : lv ? 92 : 2) // any from 88...98 ?! // [FOHCIH]
    

    /LE: on EOS-M setting it at 0 breaks ML menu operations, arrows (pressing up/down/right/left) no longer work.

  33. Alex

    It's a workaround, not a proper fix. The menu still timeouts, flickers, and during that short period, there is a risk of changing some Canon setting by mistake (depending on what dialog is behind ML menu).

  34. Koh Jaen

    Hey Guys

    Thanks for the awesome tools. I have a Canon 6D, and have the same issue (when in live-view and viewing the ML menu). At first I thought perhaps it was just me, but then I stumbled upon this.

    Anyways, just letting y'all know.

    Keep up the good work. Would love to contribute, just need the time!

  35. Alex

    Just noticed some parts of EOS M's LiveView are working in QEMU (after pressing I(NFO) a few times). For example, pressing the up arrow brings the drive mode dialog (single, continuous, self-timer and so on). However, this dialog doesn't time out. Is this true on the physical camera, or it's just an emulation bug?

    If it's the latter, the timeout decision might be taken on the MPU.

    A long press on the down arrow makes the screen white for a moment. This one is supposed to open ML menu, but for some reason it doesn't work in the emulation.

    A short press on the down arrow (after latest commit) does nothing. What's this key supposed to do on a vanilla EOS M (without ML)?

    Pressing LEFT or RIGHT will move the focus box horizontally.

    A startup log (dm-spy-experiments branch) with mpu_send/mpu_recv stubs, catching both opening and auto-closing ML menu, would be very helpful. Caveat: LiveView creates a lot of logs, so you may either try to allocate a few MB for the log, or silence some messages.

  36. Daniel Fort

    The Trash button has several functions depending on what mode the screen is in. The default is to center the AF box. The manual doesn't call it the Trash button so it is hard to search for the various functions but the Custom Functions(CFn) menu shows some of the tricks it can do.

    VRAM0.jpg

    One more if you scroll down:

    VRAM1.jpg

    I'm having problems creating a startup log. Compiling dm-spy-experiments branch with CONFIG_DEBUG_INTERCEPT_STARTUP=y and the camera just hangs. Lots of LED action for a few minutes then the light goes solid. LiveView never comes up. Needs a battery pull to recover.

  37. Daniel Fort

    You move it up and down with your finger--on the touch screen. That build you pointed out has the same issue. Maybe I'm not waiting long enough? I let it run for several minutes.

    I'll try following your instructions to see if I can get it working. Uh--where do I allocate a few MB of memory? You mean here?

    dm-spy.c

    /* the buffer is reallocated early in the boot process
     * we can't tell in advance how much free space will be eventually
     */
    #define BUF_SIZE_MALLOC (512*1024)
    
  38. Alex

    Memory amount is tuned from there, but only with CONFIG_DEBUG_INTERCEPT (without STARTUP) it will use our memory backend (so it should be able to allocate some 10-20 MB without much fuss). The one with STARTUP allocates from AllocateMemory (hardcoded), though it can be changed (but requires some fiddling).

  39. Daniel Fort

    Here is an EOSM startup log file using the build posted on Sept. 11. Turns out that after letting it run for several minutes it did save a log. If it doesn't work I can try some of your suggestions--I've already tried a couple but no luck. Yes, I know I've done this before without issues.

  40. Alex

    That's too verbose; try disabling LOG_INTERRUPTS and everything under CONFIG_DIGIC_V in dm-spy-extra.c. That will still miss a complete menu cycle, so you'll still have to either allocate a couple of MB for the log, or reduce verbosity even more.

    An easy way would be to accept only the DebugMsg calls coming from ML (class == 0 && level == 0).

  41. Alex

    You've got valid logs, so it must be working. The troubleshooting section was there because you said you have trouble getting any logs (and battery pull was needed). Now undo these things (maybe one by one) and try to get some log covering both ML menu opening (in LV) and closing (because of timeout).

    You'll have to do that with the available resources (limited memory available during startup, limited CPU time especially in LiveView, not all memory addresses can be dereferenced, some resulting in lockup...) That's why you'll have to experiment with the code, adjust verbosity for certain things, filter what messages get logged...

    I don't know in advance what messages are relevant for this; I've assumed MPU ones might be; maybe also some of the many GUI messages, or CancelTimer, but there are many of those (so the buffer gets filled pretty quickly).

    If the log gets trimmed (easy to tell from file size), you need either more memory, or less verbosity.

    To know how much memory you have available for startup logging, look in Debug -> Free memory -> AllocateMemory. Leave a few hundreds of KB for the system and use the rest for logging.

    To get even more memory, see previous advice.

  42. Daniel Fort

    Ok--I know that this isn't there yet but making some progress.

    What was causing the EOSM to hang was the calls to dm_spy_extra_install. It still worked with dm_spy_extra_uninstall but the Debug menu was showing an "unpatch" error. Regressed everything except those calls.

    I also fiddled with the memory allocation. I'm probably close to the limit because the LV is showing a pink cast but got much larger startup logs.

    It looks like you're looking for what is going on with the ML menu timing out. I remember that was "fixed" a while back with a routine that would refresh the screen before it times out but this resulted in the LV appearing in the focus area through the ML menu for a brief moment when it kicks in. On the dm-spy-experiments build all that happens is that a small red icon flashes on the bottom right of the screen.

    Screen Shot 2017-10-26 at 6.39.33 PM.jpg

    So isn't it necessary to create a log that shows the ML menus opening and timing out? That wouldn't be in a startup log would it?

  43. Daniel Fort

    Here is a log (not a startup) where the only action was to bring up the ML menu by using the down (trash) button then waiting until that red icon appeared in the lower right corner of the screen. Yeah, a lot of "Evf" noise in there but maybe what you're looking for is in there?

  44. Alex

    The last log covers about 2.7 seconds and does not cover the menu opening. If the log is not a startup one, you could even try 32 MB (but you still won't catch the menu timing out).

    You do need the dm_spy_extra stuff, at least with mpu_send and mpu_recv. Comment out all other stubs from there if it's still causing trouble:

    static struct logged_func logged_functions[] = {
        /* dummy entry, just to check cache conflicts */
        { (uint32_t) &DryosDebugMsg, "DebugMsg" },
    
        #ifdef CONFIG_EOSM
        { 0x1DD2C, "mpu_send", 2, mpu_send_log },    /* dwSize < TXBD_DATA_SIZE */
        {  0x36A0, "mpu_recv", 1, mpu_recv_log },    /* registered in InitializeIntercom as CBR */
        #endif
    }
    

    The pink flash is likely a sign of CPU usage (logging all this stuff requires lots of CPU time). FPS override usually helps; there's even a very simple version in fps_log. If it's not too bad, you could leave it like that and just silence the Evf messages (about 60% of the lines). The ones from Epp and AeWb are also worth silencing (about 15% of the lines). These are easily identified by something like: if (streq(current_task->name, "Evf")).

    To catch the menu timing out, the easiest way is to log only mpu_send/recv and silence out everything else, but that way you'll also throw away useful info. Still, pure MPU logs (without any context) are better than nothing.

  45. Daniel Fort

    Another try. This time commented out pretty much all of the stubs. The action was to start the log, press the Trash button (which on the EOSM is on the wheel) and immediately stop logging. I searched for "button" in the log and there are several instances like:

    DE388> GuiMainTas:ff0d7a4c:84:01: GUI_CONTROL:84
    DE3E3> GuiMainTas:ff1c5808:84:03: GUICMD_PRESS_BUTTON_SOMETHING(0x0)
    

    I'll try to catch the menu timing out later. Got called into work.

    EDIT - Ok, I'm a little lost. How do I skip the Evf, Epp and AeWb lines?

  46. Daniel Fort

    New log, dm_spy_extra_install/dm_spy_extra_uninstall restored, most stubs commented out, only action was Trash button to bring up ML menu.

    Interesting this works with CONFIG_DEBUG_INTERCEPT but hangs and needs a battery pull with CONFIG_DEBUG_INTERCEPT_STARTUP.

    Still not sure where to insert this:

    if (streq(current_task->name, "Evf"))
    
  47. Daniel Fort

    Another startup log. This time commenting out the patch hook function in dm_spy_extra_install. This is what was causing the camera to hang with CONFIG_DEBUG_INTERCEPT_STARTUP.

                if (check_no_conflicts(i))
                {
    //                patch_hook_function(
    //                    logged_functions[i].addr, MEM(logged_functions[i].addr),
    //                    logged_functions[i].log_func ? logged_functions[i].log_func : generic_log,
    //                    logged_functions[i].name
    //                );
                }
    

    So there must be something that check_no_conflicts isn't catching. It also might explain why it why it works with QEMU but not in camera.

  48. Alex

    More likely, one of the patched functions is misbehaving somehow. You could try doing nothing in that function (it's generic_log, unless specified otherwise in the stub definition).

    None of the latest logs have MPU messages.

    The Evf test goes in my_DebugMsg (by default, engio messages are suppressed).

  49. Alex

    Updated dm-spy-experiments to record about 20 seconds of LiveView in 2 MB, and also enabled MPU messages everywhere (tested on 5D3). Logs are also welcome from 6D owners.

    Test builds

  50. Daniel Fort

    New logs using the latest dm-spy-experiments without any modifications. EOSM still hangs with the startup log but this time I noticed that it logged my shutdown attempts so maybe this is useful. The other log is an attempt to log the Trash (down button) only and this time there are MPU messages.

    Still to do is to try and log the ML Menu time out but that will be tricky. Is there any way to know if it has been successfully logged? I take it that we need to take out those Evf, Epp and AeWb lines.

  51. Daniel Fort

    Finally got a log without the Evf, Epp and AeWb lines. Tried a few times and think maybe this log captures the ML Menu time out issue. Turned on logging, opened ML menu and waited until the red icon appeared in the lower right corner of LV screen then immediately stopped logging.

  52. Alex

    Yes, the last log captures the menu timeout.

    SetGUIRequestMode(90) is when entering ML menu.

    SetGUIRequestMode(42) - maybe that's the menu times out? It's quickly followed by SetGUIRequestMode(90) from ML menu task.

    SetGUIRequestMode(0) - probably shutdown; it's preceded by some sensor cleaning stuff.

    However, the log is missing MPU messages. These are important. Is any of them causing crashes?

  53. Alex

    Managed to get ML menu, but I need to fake the display state (the LiveView emulation doesn't go as far as turning on the display). The menu doesn't time out in the emulation. Still, enabling the MPU messages in the logs could give some clues.

    If you press UP in LiveView, do you get the drive mode dialog? Does this dialog time out on a real EOS M? If so, can you also catch this timeout in the logs?

  54. Alex

    That one only covers the start of menu, not the timeout (the log was trimmed). This branch has the new DryOS hooks, so it should accept 2 MB for the logging buffer.

  55. Daniel Fort

    @Audionut Those test builds I posted are already outdate so I removed them. Looks like the 6D testers that are left can compile so I won't post updated builds for now.

    @Alex Pressing UP in LiveView on the EOSM goes to this Canon screen:

    EOSM_up_button_Canon_menu.jpg

    Timeout on this screen seems to be by design. I removed ML and the timeout still happens. Tried to capture it in this log.

  56. Alex

    They are present in your "vanilla" logs, and also in Audionut's logs. They are also present in your older logs (from January iirc) from 700D and EOSM.

  57. Daniel Fort

    Couldn't see the forest through the trees so I re-read all the posts on this issue and think I get it now. So the menu timeout isn't visible because it was "fixed" a while back but that wasn't a proper fix--something like a fake shutter half-press event on a timer to keep the ML menu open. On the EOSM that event shows a small red wheel icon in the lower right of the screen.

    MPU events are showing up in dm-spy-experiments but when I tried trimming down the log outputs for the EOSM it no longer shows the necessary MPU events.

    Merging new-dryos-task-hooks allows for larger log files so it is safe to increase the allocated memory to 2 MB. So I took the latest dm-spy-experiments and increased the memory:

    /* the buffer is reallocated early in the boot process
     * we can't tell in advance how much free space will be eventually
     */
    #define BUF_SIZE_MALLOC (2048*1024) // Temporarily increased from 512*1024 for testing
    

    On the 700D I ran a new startup log, this time opening up the ML menu during startup and hopefully caught the timeout issue.

    On the EOSM there is a problem running the patch_hook_function (camera hangs) which might be needed to log the MPU events? Maybe check_no_conflicts isn't catching a conflict on the EOSM?

  58. Alex

    The 700D log didn't catch the timeout issue, but it shows the action of opening ML menu (and also has MPU messages). Hold a second - the 700D doesn't even have menu timeout!

    "Merging new-dryos-task-hooks allows for larger log files" - this only applies to 6D, as there's a small bug in unified (it reserves way too much for autoexec.bin).

    On EOS M, if you comment out the contents of mpu_send_log and mpu_recv_log, but keep the patch_hook_function, does it still crash? If yes, it's from the patch backend; if not, it's from whatever the two logging functions do.

    Can you comment out only one of them to see which one crashes?

  59. Daniel Fort

    Now we're getting somewhere. On the EOSM with both mpu_send/mpu_recv commented out it works fine but of course no mpu events. Only mpu_recv commented out it also works fine and saves mpu events. Only mpu_send commented out camera hangs and it does create a crash log.

    ASSERT: !IS_ERROR( TryPostEvent( this->hTaskClass, this, EV_VD_GMT, NULL, 0 ) )
    at ./Gmt/GmtState.c:6155, **INT-6Ah**:ff17a5a0
    lv:0 mode:0
    
    PropMgr stack: 27bfa8 [17cf68-17bf68]
    0x0009E558 @ 9e844:27bfa8
    
    Magic Lantern version : Nightly.2017Oct29.EOSM202
    Mercurial changeset   : 8c20bc63549c+ (dm-spy-experiments)
    Built on 2017-10-29 17:45:14 UTC by rosiefort@RosieFoComputer.
    Free Memory  : 155K + 1929K
    
  60. Daniel Fort

    Another EOSM log. This time with this:

    internals.h

    /** Workaround for menu timeout in LiveView */
    // #define CONFIG_MENU_TIMEOUT_FIX
    

    Also with the undefine MPU_DELAY_SEND "fix" -- started logging, entered ML menu, waited for menu timeout then immediately stopped logging.

    Looks like undefining MPU_DELAY_SEND is necessary on the EOSM in order to log MPU events.

  61. Daniel Fort

    Ok--this is strange. I forgot to undefine MPU_DELAY_SEND before that last test yet the MPU messages are there. What was different on this test was that it took several seconds before the red icon I was looking for appeared. So maybe it takes a while before it starts logging MPU events? That's the job of MPU_DELAY_SEND?

    In any case that last EOSM test run was done on an unmodified dm-spy-experiments build with CONFIG_DEBUG_INTERCEPT=y in Makefile.user.

  62. Daniel Fort

    One more time before heading to work.

    dm-spy.c

    #define BUF_SIZE_MALLOC (2048*1024)
    

    dm-spy-extra.c

    #undef LOG_MALLOC_CALLS
    

    [EDIT] I meant #undef MPU_DELAY_SEND

    Though it looks like that wasn't necessary for this log. That's only needed for the EOSM when creating a startup log, right? More specifically an in camera startup log. Now if the EOSM can handle 2MB log files I suppose that applies to other cameras that can use the new dryos task hooks. Speaking of new-dryos-task-hooks, what's with all the foo'ing files that "make clean" doesn't remove? Ok--I'm going off topic, just looking at ways to make things easier on the next guy that uses dm-spy-experiments.

  63. Log in to comment