TBT 3 WS G2 dock update failing with latest fwupd

[mrhpearson]

Trying to install https://fwupd.org/lvfs/firmware/8790 on TBT3 WS G2 dock. Using Fedora 35 on P1 G3 and it is failing with fwupd version 1.7.1

Attached are the logs from fwupd and fwupdmgr. Failure message reported is: failed to get device before update attach: failed to wait for detach replug: device 3281dd62e64cfca4eec0492d675e1d4deb1b1cea did not come back I believe this is the MSP430.

log.txt dock-update.txt

This works with older versions of fwupd (1.5.11). The below log is from a system running Ubuntu, where it worked with 1.5.11 and then failed when I used the 1.7.1 on the same system/OS log_1.5.11.txt

Let me know if there is anything else I can help with for debugging

[hughsie]

Notes for me: The MSP430 device auto-reboots when the firmware write gets to 100% and doesn't require attach. Will continue debugging on Monday.

[hughsie]

So the weirdness seems to be that the USB context seems to stop emitting hotplug events, but only after the MSP430 device is updated. You can even insert a device on a different parent to the dock and it's ignored completely. Continuing to debug.

[hughsie]

That would do it:

==184942== Invalid read of size 8
==184942==    at 0x4DF9261: UnknownInlinedFun (gusb-context.c:334)
==184942==    by 0x4DF9261: g_usb_context_idle_hotplug_cb (gusb-context.c:390)
==184942==    by 0x4CC352A: g_idle_dispatch (gmain.c:5897)
==184942==    by 0x4CC733E: UnknownInlinedFun (gmain.c:3381)
==184942==    by 0x4CC733E: g_main_context_dispatch (gmain.c:4099)
==184942==    by 0x4D1C2B7: g_main_context_iterate.constprop.0 (gmain.c:4175)
==184942==    by 0x4CC49E2: g_main_context_iteration (gmain.c:4240)
==184942==    by 0x41CF7F: fu_device_list_wait_for_replug (fu-device-list.c:886)
==184942==    by 0x421C43: fu_engine_get_device (fu-engine.c:2803)
==184942==    by 0x4229B6: fu_engine_attach (fu-engine.c:3035)
==184942==    by 0x4229B6: fu_engine_install_blob (fu-engine.c:3302)
==184942==    by 0x422EAB: fu_engine_install_release (fu-engine.c:2517)
==184942==    by 0x423600: fu_engine_install (fu-engine.c:2749)
==184942==    by 0x4237FC: fu_engine_install_tasks (fu-engine.c:2167)
==184942==    by 0x4182BC: fu_main_authorize_install_queue (fu-main.c:802)
==184942==  Address 0x6b19cf8 is 120 bytes inside a block of size 136 free'd
==184942==    at 0x48440E4: free (vg_replace_malloc.c:872)
==184942==    by 0x4CCC0BC: g_free (gmem.c:199)
==184942==    by 0x4CE66CF: g_slice_free1 (gslice.c:1183)
==184942==    by 0x4C4CF7B: g_type_free_instance (gtype.c:2001)
==184942==    by 0x4DF92EE: UnknownInlinedFun (gusb-context.c:375)
==184942==    by 0x4DF92EE: g_usb_context_idle_hotplug_cb (gusb-context.c:396)
==184942==    by 0x4CC352A: g_idle_dispatch (gmain.c:5897)
==184942==    by 0x4CC733E: UnknownInlinedFun (gmain.c:3381)
==184942==    by 0x4CC733E: g_main_context_dispatch (gmain.c:4099)
==184942==    by 0x4D1C2B7: g_main_context_iterate.constprop.0 (gmain.c:4175)
==184942==    by 0x4CC49E2: g_main_context_iteration (gmain.c:4240)
==184942==    by 0x41CF7F: fu_device_list_wait_for_replug (fu-device-list.c:886)
==184942==    by 0x421C43: fu_engine_get_device (fu-engine.c:2803)
==184942==    by 0x4229B6: fu_engine_attach (fu-engine.c:3035)
==184942==    by 0x4229B6: fu_engine_install_blob (fu-engine.c:3302)
==184942==  Block was alloc'd at
==184942==    at 0x484186F: malloc (vg_replace_malloc.c:381)
==184942==    by 0x4CCF788: g_malloc (gmem.c:106)
==184942==    by 0x4CE71B4: g_slice_alloc (gslice.c:1072)
==184942==    by 0x4CE781D: g_slice_alloc0 (gslice.c:1098)
==184942==    by 0x4C522DA: g_type_create_instance (gtype.c:1901)
==184942==    by 0x4C39C9C: g_object_new_internal (gobject.c:1939)
==184942==    by 0x4C3B68A: g_object_new_valist (gobject.c:2295)
==184942==    by 0x4AB80ED: g_initable_new_valist (ginitable.c:244)
==184942==    by 0x4AB81BC: g_initable_new (ginitable.c:162)
==184942==    by 0x431424: fu_usb_backend_setup (fu-usb-backend.c:51)
==184942==    by 0x48BAFE0: fu_backend_setup (fu-backend.c:125)
==184942==    by 0x429143: fu_engine_load (fu-engine.c:6911)

[hughsie]

Adding in some debugging to weak ref the USB context:

14:12:34:0423 FuBackend            [Thread 0x7fffe3b85640 (LWP 201155) exited]
GUsbContext 0x47cda0 was finalized from under our feet!

Thread 1 "fwupd" received signal SIGTRAP, Trace/breakpoint trap.
g_logv (log_domain=0x439d3e "FuBackend", log_level=G_LOG_LEVEL_CRITICAL, format=<optimized out>, args=<optimized out>) at ../glib/gmessages.c:1417
1417          g_private_set (&g_log_depth, GUINT_TO_POINTER (depth));
Missing separate debuginfos, use: dnf debuginfo-install ModemManager-glib-1.18.2-1.fc35.x86_64 efivar-libs-37-17.fc35.x86_64 libacl-2.3.1-2.fc35.x86_64 libassuan-2.5.5-3.fc35.x86_64 libcap-2.48-3.fc35.x86_64 libgcrypt-1.9.4-1.fc35.x86_64 libmbim-1.26.0-1.fc35.x86_64 libqmi-1.30.2-1.fc35.x86_64 libqrtr-glib-1.0.0-2.fc35.x86_64 libsmbios-2.4.3-4.fc35.x86_64 polkit-libs-0.120-1.fc35.x86_64 protobuf-c-1.4.0-1.fc35.x86_64 systemd-libs-249.7-2.fc35.x86_64 tpm2-tss-3.1.0-3.fc35.x86_64
(gdb) bt
#0  g_logv (log_domain=0x439d3e "FuBackend", log_level=G_LOG_LEVEL_CRITICAL, format=<optimized out>, args=<optimized out>) at ../glib/gmessages.c:1417
#1  0x00007ffff7ac5753 in g_log (log_domain=<optimized out>, log_level=<optimized out>, format=<optimized out>) at ../glib/gmessages.c:1455
#2  0x00007ffff7bbf6c7 in weak_refs_notify (data=0x51f800) at ../gobject/gobject.c:2964
#3  0x00007ffff7a9e85e in g_data_set_internal (datalist=0x47cdb0, key_id=<optimized out>, new_data=<optimized out>, new_destroy_func=<optimized out>, dataset=0x0) at ../glib/gdataset.c:407
#4  0x00007ffff7bc3b14 in g_object_unref (_object=<optimized out>) at ../gobject/gobject.c:3540
#5  g_object_unref (_object=0x47cda0) at ../gobject/gobject.c:3470
#6  0x00007ffff7a1f4f0 in g_usb_context_idle_helper_free (helper=0x7fffdc000bf0) at ../gusb/gusb-context.c:387
#7  g_usb_context_idle_hotplug_cb (user_data=user_data@entry=0x7fffdc000bf0) at ../gusb/gusb-context.c:408
#8  0x00007ffff7ab952b in g_idle_dispatch (source=0x7fffdc002f90, callback=0x7ffff7a1f410 <g_usb_context_idle_hotplug_cb>, user_data=0x7fffdc000bf0) at ../glib/gmain.c:5897
#9  0x00007ffff7abd33f in g_main_dispatch (context=0x4752c0) at ../glib/gmain.c:3381
#10 g_main_context_dispatch (context=0x4752c0) at ../glib/gmain.c:4099
#11 0x00007ffff7b122b8 in g_main_context_iterate.constprop.0 (context=context@entry=0x4752c0, block=block@entry=0, dispatch=dispatch@entry=1, self=<optimized out>) at ../glib/gmain.c:4175
#12 0x00007ffff7aba9e3 in g_main_context_iteration (context=0x4752c0, context@entry=0x0, may_block=may_block@entry=0) at ../glib/gmain.c:4240
#13 0x000000000041cf80 in fu_device_list_wait_for_replug (self=0x478500 [FuDeviceList], error=error@entry=0x7fffffffdd38) at ../src/fu-device-list.c:886
#14 0x0000000000421c44 in fu_engine_get_device (self=self@entry=0x47b850 [FuEngine], device_id=device_id@entry=0x706fd0 "3281dd62e64cfca4eec0492d675e1d4deb1b1cea", error=error@entry=0x7fffffffdd38)
    at ../src/fu-engine.c:2803
#15 0x00000000004229b7 in fu_engine_attach (error=0x7fffffffdd38, progress=0x6f8470 [FuProgress], device_id=0x706fd0 "3281dd62e64cfca4eec0492d675e1d4deb1b1cea", self=0x47b850 [FuEngine])
    at ../src/fu-engine.c:3035
#16 fu_engine_install_blob
    (self=self@entry=0x47b850 [FuEngine], device=device@entry=0x5ccb90 [FuVliUsbhubMsp430Device], blob_fw=blob_fw@entry=0x701260, progress=progress@entry=0x6f8370 [FuProgress], flags=flags@entry=FWUPD_INSTALL_FLAG_ALLOW_REINSTALL, feature_flags=feature_flags@entry=63, error=0x7fffffffdd38) at ../src/fu-engine.c:3302

[hughsie]

@mrhpearson can you compare the libgusb versions between working and not-working? https://github.com/hughsie/libgusb/pull/55 seems to fix the issue for me.

[hughsie]

also be careful that libgusb gets built as a subproject if not new enough.

[mrhpearson]

Ubuntu was using 0.3.4 and Fedora 0.3.8 I built the patched version of libgusb and installed (and did 'sudo ldconfig'). I'm still seeing the issue - do I need to rebuild fwupd as well? Thanks! mark

[hughsie]

@mrhpearson can you try the libgusb here please: https://people.freedesktop.org/~hughsient/fedora/32/x86_64/ -- you can install the fwupd build to if that makes things easier too.

[mrhpearson]

Hi @hughsie My apologies - I completely lost track of this one over the holidays and then in the inbox swamp from the new year. Testing again today I get:

[banther@p1g3-uma fwupd-debug]$ fwupdmgr install 38866cf5bb914816ba4e00b9ecb3283a89185553edb3ab41b05f7c383fff43f2-TRDOCK_3180.cab --allow-reinstall
Decompressing…           [***************************************]
Authenticating…          [   -                                   ]
Authenticating…          [***************************************]
Waiting…                 [***************                        ] 2 minute remaining…failed to get device before update prepare: failed to get device after replug: device ID e487b5ff307494d6ff44d1b6dc1312bb69b0fe90 was not found

The error message gets displayed immediately as the dock comes back on (from presumably updating it's FW?). Is this just a slight timing issue and the dock needs just a few more seconds before it responds? The device is showing up from fwupdmgr get-devices afterwards

Looks like the FW is updated correctly, so it's just a detection thing.

I'm running fwupd 1.7,4 (on Fedora 35). I confirmed libgusb is 0.3.9 - so didn't install the versions you built

Mark

[hughsie]

I can reproduce the same failure; mea culpa. https://github.com/fwupd/fwupd/pull/4255 fixes it for me.

[mrhpearson]

Sweet :) Thanks - I'll give that a spin