winit icon indicating copy to clipboard operation
winit copied to clipboard
verified publisher icon rust-windowing

Trace window messages

Open maroider opened this issue 3 years ago • 2 comments

  • [x] Tested on all platforms changed
  • ~~Added an entry to CHANGELOG.md if knowledge of this change could be valuable to users~~
  • ~~Updated documentation to reflect any user-facing changes, including notes of platform-specific behavior~~
  • ~~Created or updated an example program if it would help users understand this functionality~~
  • ~~Updated feature matrix, if new features were added or implemented~~

This adds tracing of all window messages sent to user-created windows. Currently, this excludes tracing messages on the "tread messsage target" window. Messages that are received in a re-entrant manner are indented, and the hwnd, wparam and lparam parameters are formatted such that they are aligned across log messages, regardless of the level of reentrancy (up to a point, of course). I'd like to thank @swooster for showing me their own code that did something similar.

To achieve this, I had to mess with the window setup and teardown code (again).

I ended up writing and testing this under wine, but I expect that it'll work just fine on Windows proper.

This is an example of the output you can expect 
2022-02-05 15:20:09,252 TRACE [winit::platform_impl::platform::window] Calling CreateWindowExW
2022-02-05 15:20:09,253 TRACE [winit::platform_impl::platform::event_loop] WM_GETMINMAXINFO            hwnd=0x1004a  w=0                 l=0x21e560
2022-02-05 15:20:09,253 TRACE [winit::platform_impl::platform::event_loop] WM_NCCREATE                 hwnd=0x1004a  w=0                 l=0x21e860
2022-02-05 15:20:09,253 TRACE [winit::platform_impl::platform::event_loop]   0xC02D                    hwnd=0x1004a  w=1                 l=0x0
2022-02-05 15:20:09,254 TRACE [winit::platform_impl::platform::event_loop]   WM_STYLECHANGING          hwnd=0x1004a  w=fffffffffffffff0  l=0x21ccf8
2022-02-05 15:20:09,254 TRACE [winit::platform_impl::platform::event_loop]   WM_STYLECHANGED           hwnd=0x1004a  w=fffffffffffffff0  l=0x21ccf8
2022-02-05 15:20:09,254 TRACE [winit::platform_impl::platform::event_loop]   WM_STYLECHANGING          hwnd=0x1004a  w=ffffffffffffffec  l=0x21ccf8
2022-02-05 15:20:09,254 TRACE [winit::platform_impl::platform::event_loop]   WM_STYLECHANGED           hwnd=0x1004a  w=ffffffffffffffec  l=0x21ccf8
2022-02-05 15:20:09,254 TRACE [winit::platform_impl::platform::event_loop]   WM_WINDOWPOSCHANGING      hwnd=0x1004a  w=0                 l=0x21cdc0
2022-02-05 15:20:09,254 TRACE [winit::platform_impl::platform::event_loop]   WM_NCCALCSIZE             hwnd=0x1004a  w=1                 l=0x21ccd0
2022-02-05 15:20:09,254 TRACE [winit::platform_impl::platform::event_loop]   WM_WINDOWPOSCHANGED       hwnd=0x1004a  w=0                 l=0x21cdc0
2022-02-05 15:20:09,255 TRACE [winit::platform_impl::platform::event_loop]     WM_MOVE                 hwnd=0x1004a  w=0                 l=0x170004
2022-02-05 15:20:09,255 TRACE [winit::platform_impl::platform::event_loop]     WM_SIZE                 hwnd=0x1004a  w=0                 l=0x3690598
2022-02-05 15:20:09,255 TRACE [winit::platform_impl::platform::event_loop]   0xC02D                    hwnd=0x1004a  w=0                 l=0x0
2022-02-05 15:20:09,256 TRACE [winit::platform_impl::platform::event_loop] WM_NCCALCSIZE               hwnd=0x1004a  w=0                 l=0x21e750
2022-02-05 15:20:09,256 TRACE [winit::platform_impl::platform::event_loop] WM_CREATE                   hwnd=0x1004a  w=0                 l=0x21e860
2022-02-05 15:20:09,256 TRACE [winit::platform_impl::platform::event_loop]   WM_SHOWWINDOW             hwnd=0x1004a  w=1                 l=0x0
2022-02-05 15:20:09,257 TRACE [winit::platform_impl::platform::event_loop]   WM_WINDOWPOSCHANGING      hwnd=0x1004a  w=0                 l=0x21d3c0
2022-02-05 15:20:09,257 TRACE [winit::platform_impl::platform::event_loop]   WM_GETICON                hwnd=0x1004a  w=1                 l=0x0
2022-02-05 15:20:09,257 TRACE [winit::platform_impl::platform::event_loop]   WM_GETICON                hwnd=0x1004a  w=0                 l=0x0
2022-02-05 15:20:09,257 TRACE [winit::platform_impl::platform::event_loop]   WM_QUERYNEWPALETTE        hwnd=0x1004a  w=0                 l=0x0
2022-02-05 15:20:09,258 TRACE [winit::platform_impl::platform::event_loop]   WM_ACTIVATEAPP            hwnd=0x1004a  w=1                 l=0x0
2022-02-05 15:20:09,258 TRACE [winit::platform_impl::platform::event_loop]   WM_NCACTIVATE             hwnd=0x1004a  w=1                 l=0x0
2022-02-05 15:20:09,258 TRACE [winit::platform_impl::platform::event_loop]   WM_ACTIVATE               hwnd=0x1004a  w=1                 l=0x0
2022-02-05 15:20:09,259 TRACE [winit::platform_impl::platform::event_loop]     WM_IME_SELECT           hwnd=0x1004a  w=1                 l=0x25f5c0
2022-02-05 15:20:09,259 TRACE [winit::platform_impl::platform::event_loop]     WM_IME_SETCONTEXT       hwnd=0x1004a  w=1                 l=0xc000000f
2022-02-05 15:20:09,259 TRACE [winit::platform_impl::platform::event_loop]     WM_SETFOCUS             hwnd=0x1004a  w=0                 l=0x0
2022-02-05 15:20:09,259 TRACE [winit::platform_impl::platform::event_loop]   WM_NCPAINT                hwnd=0x1004a  w=1                 l=0x0
2022-02-05 15:20:09,260 TRACE [winit::platform_impl::platform::event_loop]   WM_ERASEBKGND             hwnd=0x1004a  w=3701003f          l=0x0
2022-02-05 15:20:09,260 TRACE [winit::platform_impl::platform::event_loop]   WM_WINDOWPOSCHANGED       hwnd=0x1004a  w=0                 l=0x21d3c0
2022-02-05 15:20:09,260 TRACE [winit::platform_impl::platform::event_loop]   WM_SIZE                   hwnd=0x1004a  w=0                 l=0x3690598
2022-02-05 15:20:09,260 TRACE [winit::platform_impl::platform::event_loop]   WM_MOVE                   hwnd=0x1004a  w=0                 l=0x170004
2022-02-05 15:20:09,260 TRACE [winit::platform_impl::platform::event_loop]   0xC02D                    hwnd=0x1004a  w=1                 l=0x0
2022-02-05 15:20:09,260 TRACE [winit::platform_impl::platform::event_loop]   WM_STYLECHANGING          hwnd=0x1004a  w=fffffffffffffff0  l=0x21d3e8
2022-02-05 15:20:09,261 TRACE [winit::platform_impl::platform::event_loop]   WM_STYLECHANGED           hwnd=0x1004a  w=fffffffffffffff0  l=0x21d3e8
2022-02-05 15:20:09,261 TRACE [winit::platform_impl::platform::event_loop]   WM_STYLECHANGING          hwnd=0x1004a  w=ffffffffffffffec  l=0x21d3e8
2022-02-05 15:20:09,261 TRACE [winit::platform_impl::platform::event_loop]   WM_STYLECHANGED           hwnd=0x1004a  w=ffffffffffffffec  l=0x21d3e8
2022-02-05 15:20:09,261 TRACE [winit::platform_impl::platform::event_loop]   WM_WINDOWPOSCHANGING      hwnd=0x1004a  w=0                 l=0x21d4b0
2022-02-05 15:20:09,261 TRACE [winit::platform_impl::platform::event_loop]   WM_NCCALCSIZE             hwnd=0x1004a  w=1                 l=0x21d3c0
2022-02-05 15:20:09,261 TRACE [winit::platform_impl::platform::event_loop]   WM_NCPAINT                hwnd=0x1004a  w=1                 l=0x0
2022-02-05 15:20:09,262 TRACE [winit::platform_impl::platform::event_loop]   WM_ERASEBKGND             hwnd=0x1004a  w=3701003f          l=0x0
2022-02-05 15:20:09,262 TRACE [winit::platform_impl::platform::event_loop]   WM_WINDOWPOSCHANGED       hwnd=0x1004a  w=0                 l=0x21d4b0
2022-02-05 15:20:09,262 TRACE [winit::platform_impl::platform::event_loop]   0xC02D                    hwnd=0x1004a  w=0                 l=0x0
2022-02-05 15:20:09,262 TRACE [winit::platform_impl::platform::event_loop]   WM_WINDOWPOSCHANGING      hwnd=0x1004a  w=0                 l=0x21d6e0
2022-02-05 15:20:09,262 TRACE [winit::platform_impl::platform::event_loop]     WM_GETMINMAXINFO        hwnd=0x1004a  w=0                 l=0x21c990
2022-02-05 15:20:09,263 TRACE [winit::platform_impl::platform::event_loop]   WM_NCCALCSIZE             hwnd=0x1004a  w=1                 l=0x21d5f0
2022-02-05 15:20:09,268 TRACE [winit::platform_impl::platform::event_loop]   WM_NCPAINT                hwnd=0x1004a  w=1                 l=0x0
2022-02-05 15:20:09,268 TRACE [winit::platform_impl::platform::event_loop]   WM_ERASEBKGND             hwnd=0x1004a  w=3701003f          l=0x0
2022-02-05 15:20:09,269 TRACE [winit::platform_impl::platform::event_loop]   WM_WINDOWPOSCHANGED       hwnd=0x1004a  w=0                 l=0x21d6e0
2022-02-05 15:20:09,269 TRACE [winit::platform_impl::platform::event_loop]     WM_SIZE                 hwnd=0x1004a  w=0                 l=0x800080
2022-02-05 15:20:09,269 TRACE [winit::platform_impl::platform::event_loop] WM_SIZE                     hwnd=0x1004a  w=0                 l=0x800080
2022-02-05 15:20:09,269 TRACE [winit::platform_impl::platform::event_loop] WM_MOVE                     hwnd=0x1004a  w=0                 l=0x170004
2022-02-05 15:20:09,269 TRACE [winit::platform_impl::platform::window] Returned from CreateWindowExW
2022-02-05 15:20:09,269 TRACE [winit::platform_impl::platform::event_loop] WM_PAINT                    hwnd=0x1004a  w=0                 l=0x0
2022-02-05 15:20:09,269 TRACE [winit::platform_impl::platform::event_loop] WM_PAINT                    hwnd=0x1004a  w=0                 l=0x0
2022-02-05 15:20:09,270 TRACE [winit::platform_impl::platform::event_loop] WM_MOUSEACTIVATE            hwnd=0x1004a  w=1004a             l=0x2010005
2022-02-05 15:20:09,270 TRACE [winit::platform_impl::platform::event_loop] WM_WINDOWPOSCHANGING        hwnd=0x1004a  w=0                 l=0x21eb40
2022-02-05 15:20:09,270 TRACE [winit::platform_impl::platform::event_loop]   WM_GETMINMAXINFO          hwnd=0x1004a  w=0                 l=0x21ddf0
2022-02-05 15:20:09,270 TRACE [winit::platform_impl::platform::event_loop] WM_NCCALCSIZE               hwnd=0x1004a  w=1                 l=0x21ea50
2022-02-05 15:20:09,270 TRACE [winit::platform_impl::platform::event_loop] WM_NCPAINT                  hwnd=0x1004a  w=1                 l=0x0
2022-02-05 15:20:09,271 TRACE [winit::platform_impl::platform::event_loop] WM_ERASEBKGND               hwnd=0x1004a  w=3701003f          l=0x0
2022-02-05 15:20:09,271 TRACE [winit::platform_impl::platform::event_loop] WM_WINDOWPOSCHANGED         hwnd=0x1004a  w=0                 l=0x21eb40
2022-02-05 15:20:09,271 TRACE [winit::platform_impl::platform::event_loop]   WM_MOVE                   hwnd=0x1004a  w=0                 l=0x1a0780
2022-02-05 15:20:09,271 TRACE [winit::platform_impl::platform::event_loop]   WM_SIZE                   hwnd=0x1004a  w=0                 l=0x47b0780
2022-02-05 15:20:09,271 TRACE [winit::platform_impl::platform::event_loop] WM_NCHITTEST                hwnd=0x1004a  w=0                 l=0xec0ae4
2022-02-05 15:20:09,272 TRACE [winit::platform_impl::platform::event_loop] WM_SETCURSOR                hwnd=0x1004a  w=1004a             l=0x2000001

maroider avatar Feb 05 '22 14:02 maroider

I'm not entirely happy with how this handles reentrancy across different windows, but I think the current code is useful enough on its own. I feel like we might perhaps be better served by using something like tracing's spans instead of log at that point (granted, I haven't used tracing all that much, so I could be wrong about how useful it would be).

maroider avatar Jul 12 '22 22:07 maroider

Please ignore that automatic review request. I still need to have another look at that cross-window re-entrancy thing.

maroider avatar Nov 23 '22 18:11 maroider