Discrepancies in object IDs printed by $WAYLAND_DEBUG output

[Derek Foreman]

On 2021-08-25 3:08 p.m., Hoosier, Matt wrote:
> I observe that the IDs used to denote some wl_buffer protocol objects 
> created by a server-side factory in the $WAYLAND_DEBUG trace, differ 
> between the moment they're first announced in the callback event and 
> the later use-sites when the objects are passed to subsequent Wayland 
> protocol method invocations.


This happens because internally the id is replaced with a pointer to the 
object for the next steps in event queuing, and the debug printing code 
runs too late to see the original ids.


This is a timely complaint, as I wrote a patch for this just yesterday:

https://gitlab.freedesktop.org/wayland/wayland/-/merge_requests/172


Thanks,

Derek


> For example, using weston-simple-dmabuf-egl normally uses 
> "non-immediate" allocation of wl_buffers through the 
> zwp_linux_dmabuf_v1 protocol extension. One distinguishing feature of 
> this non-immediate technique is that the ID of the newly-built 
> protocol object is not known at the time the method to request 
> creation is made. The compositor is expected to supply it later in an 
> asynchronous event.
>
> This all works fine, but I notice in the log output that the ID of the 
> newly built object is different at point it's first announced to the 
> client:
>
> [2902569.971]  -> 
> zwp_linux_explicit_synchronization_v1 at 6.get_synchronization(new id 
> zwp_linux_surface_synchronization_v1 at 10, wl_surface at 3)
> [2902570.062]  -> zwp_linux_dmabuf_v1 at 5.create_params(new id 
> zwp_linux_buffer_params_v1 at 11)
> [2902570.076]  -> zwp_linux_buffer_params_v1 at 11.add(fd 8, 0, 0, 1024, 
> 16777216, 2)
> [2902570.095]  -> zwp_linux_buffer_params_v1 at 11.create(256, 256, 
> 875713112, 1)
> [2902572.072]  -> zwp_linux_dmabuf_v1 at 5.create_params(new id 
> zwp_linux_buffer_params_v1 at 12)
> [2902572.105]  -> zwp_linux_buffer_params_v1 at 12.add(fd 10, 0, 0, 1024, 
> 16777216, 2)
> [2902572.124]  -> zwp_linux_buffer_params_v1 at 12.create(256, 256, 
> 875713112, 1)
> [2902572.240]  -> zwp_linux_dmabuf_v1 at 5.create_params(new id 
> zwp_linux_buffer_params_v1 at 13)
> [2902572.249]  -> zwp_linux_buffer_params_v1 at 13.add(fd 12, 0, 0, 1024, 
> 16777216, 2)
> [2902572.262]  -> zwp_linux_buffer_params_v1 at 13.create(256, 256, 
> 875713112, 1)
> ...
> [2902576.893] zwp_linux_buffer_params_v1 at 11.created(new id 
> wl_buffer at 2372643520)
> [2902576.901]  -> zwp_linux_buffer_params_v1 at 11.destroy()
> [2902576.906] zwp_linux_buffer_params_v1 at 12.created(new id 
> wl_buffer at 2372643856)
> [2902576.913]  -> zwp_linux_buffer_params_v1 at 12.destroy()
> [2902576.918] zwp_linux_buffer_params_v1 at 13.created(new id 
> wl_buffer at 2372644240)
> [2902576.924]  -> zwp_linux_buffer_params_v1 at 13.destroy()
>
> So, here are the ID's of the buffers built using the non-immediate mode:
>
>   * wl_buffer at 2372643520 (0x8d6baac0)
>   * wl_buffer at 2372643856 (0x8d6bac10)
>   * wl_buffer at 2372644240 (0x8d6bad90)
>
>
> These ID's look suspicious to begin with. They do not have ID's in the 
> usual range of server-allocated object ID's (these are supposed 
> to begin at 0xff000000).
>
> But then later when the application uses these objects as parameter to 
> subsequent requests, the ID's are printed differently:
>
>     [2902577.702]  -> wl_surface at 3.attach(wl_buffer at 4278190080, 0, 0)
>     ...
>     [3183676.812]  -> wl_surface at 3.attach(wl_buffer at 4278190081, 0, 0)
>     ...
>
> So here, those are:
>
>   * wl_buffer at 4278190080 (0xff000000)
>   * wl_buffer at 4278190081 (0xff000001)
>
>
>
> Those ID's are in the expected range for server-allocated protocol 
> objects. Despite this discrepancy, the application clearly works fine; 
> the right contents appear on-screen.
>
> Is there some quirk that causes object ID's passed as parameters to 
> events to be mis-printed?
>
> -Matt