Discrepancies in object IDs printed by $WAYLAND_DEBUG output

[Hoosier, Matt]

> -----Original Message-----
> From: Derek Foreman <derek.foreman at collabora.com>
> Sent: Wednesday, August 25, 2021 3:54 PM
> To: Hoosier, Matt <Matt.Hoosier at garmin.com>; wayland-
> devel at lists.freedesktop.org
> Subject: Re: Discrepancies in object IDs printed by $WAYLAND_DEBUG
> output
> 
> CAUTION - EXTERNAL EMAIL: Do not click any links or open any attachments
> unless you trust the sender and know the content is safe.
> 
> 
> 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://urldefense.com/v3/__https://gitlab.freedesktop.org/wayland/wayla
> nd/-/merge_requests/172__;!!EJc4YC3iFmQ!Eph6m9-
> gz6SOpNOFygfXEu3p4Mc03jqKztjF1slUZHBatS5WVR6pkxqADKUehzk_zA$
> 
> 
> Thanks,
> 
> Derek

Ah, makes sense. Thanks.

> 
> 
> > 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