From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from mail-lj1-f172.google.com (mail-lj1-f172.google.com [209.85.208.172]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (No client certificate requested) by smtp.subspace.kernel.org (Postfix) with ESMTPS id 362454C84 for ; Fri, 17 Jun 2022 20:48:51 +0000 (UTC) Received: by mail-lj1-f172.google.com with SMTP id e4so5917919ljl.1 for ; Fri, 17 Jun 2022 13:48:51 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20210112; h=mime-version:references:in-reply-to:from:date:message-id:subject:to :cc; bh=ZvlmhjX5WrHl156XHjI+XlN+ZCT9UnRn+tpViHipDk4=; b=AQvbQNqjOh+vs7nV5O4ZkPwpwVG3IY/XB6qUsKlo+u+PXBU59U7UGX2SeOkfGtUFhe OGLyR7EAaHiOA5PfWmMV9H4KzkryFkxzdJuYgfRXa/59tlGXShywPbvDJszBRZ4Y4PmJ 5Uh1/5YSEVpF9HtIFUpQl5jVL1LgshkzaXE8mTSaMAsJsVDYf1dznDACdEtMyavCHglw zLEBZkjGuJ3sck9feEMZr/8ui88ly3fhgPHM0P0etLAyf1Jnm423P+biHDflkD+4PGjq KuUI5Noeudu3KiO6beAYGEY0aG5QvAcdsLv9JT0D4EKsoIkZmf0WqC0GffegxYkKqatF kUYw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to:cc; bh=ZvlmhjX5WrHl156XHjI+XlN+ZCT9UnRn+tpViHipDk4=; b=RLf67UyIZ7mhf32HRRY63InOeffsMOBDDuQ+rg5RKp/HnM8heip7KbpU1wz4dSqgcT Y892r3cTSza5bK0e0rXcM7MIMkQcdY8qrwZ+wAjX/NdtiqMyDlyHBhWAB4H4AIqsUGmx 6tCNIkbin9/F+U5Xy5GGPWxfuKKDmXlNUVf1wHy3DATz56JNc9onSpZG2S1tOr/miR3z CMJHsLnvYcG+u0MpKGMvjBov0cO82WVW2H/2mO8zQmLkzw187Z28DR6AryTUNFuWJaft m1p2YtNKx4wgh/SoQ3h5/OGU8HrrZir54emUUKFE96tbeM9s0eormlsfENjl2IGpJbBi ZyMw== X-Gm-Message-State: AJIora/GL6TCl63A2Eu8RIMkNcIlm6fP4TZqaU5ZffmWjvTG0REY1+2l nJXupbP1QVMUmDkZ8OHbVIz4tKSs5CqRqdSKen4= X-Google-Smtp-Source: AGRyM1sIFKriab8YwDUFvTn5R/ggwO4Y3nbrPnazNRow1Hj2WUYgE/JWWUOSKjHrCuDG+m3YpP66//FiqDgh8tckehc= X-Received: by 2002:a05:651c:549:b0:255:bbd2:fb8 with SMTP id q9-20020a05651c054900b00255bbd20fb8mr5859838ljp.305.1655498928997; Fri, 17 Jun 2022 13:48:48 -0700 (PDT) Precedence: bulk X-Mailing-List: regressions@lists.linux.dev List-Id: List-Subscribe: List-Unsubscribe: MIME-Version: 1.0 References: <8d5c4724-d511-39b1-21d7-116c91cada45@pengutronix.de> In-Reply-To: From: Luiz Augusto von Dentz Date: Fri, 17 Jun 2022 13:48:37 -0700 Message-ID: Subject: Re: [BUG] BLE device unpairing triggers kernel panic To: Ahmad Fatoum Cc: "linux-bluetooth@vger.kernel.org" , Marcel Holtmann , "regressions@lists.linux.dev" , Pengutronix Kernel Team Content-Type: text/plain; charset="UTF-8" Hi Ahmad, On Thu, Jun 16, 2022 at 3:38 AM Ahmad Fatoum wrote: > > Hello Luiz, > > On 16.05.22 18:37, Ahmad Fatoum wrote: > >>>> - Commit a56a1138cbd8 ("Bluetooth: hci_sync: Fix not using conn_timeout") > >>>> fixes, despite the title, what event is waited on. First Pairing works now, > >>>> but the second pairing times out and crashes the kernel: > >>>> > >>>> [ 84.191684] Bluetooth: hci0: Opcode 0x200d failed: -110 > >>>> [ 84.230478] Bluetooth: hci0: request failed to create LE connection: err -110 > >>>> [ 84.237690] Unable to handle kernel read from unreadable memory at virtual address 0000000000000ca8 > >> > >> That said the error -110 mean -ETIMEDOUT > > > > Yes, this issue remains still. I feel better about my revert > > knowing that the crash is fixed, but I'd like this regression > > here fixed upstream as well. I'll try to collect some more > > information and report back. > > I've now found time to revisit this and sprinkle around some > extra logging. This is the initial pairing that works: > > Bluetooth: entered hci_le_create_conn_sync() > Bluetooth: hci0: opcode 0x200d plen 25 > Bluetooth: hci0: event 0x0f (sent = 0x0a) > Bluetooth: hci0: BT: opcode 0x200d (sent: 0x0a) > Bluetooth: hci0: event 0x3e (sent = 0x0a) > Bluetooth: hci0: BT: subevent 0x0a (sent 0x0a) > Bluetooth: entered hci_le_meta_evt(event=0x0a) completion clause > > I unpaired on device side and then retried pairing: > > Bluetooth: entered hci_le_create_conn_sync() > Bluetooth: hci0: opcode 0x200d plen 25 > Bluetooth: hci0: event 0x0f (sent = 0x0a) > Bluetooth: hci0: BT: opcode 0x200d (sent: 0x0a) > Bluetooth: entered hci_abort_conn() > Bluetooth: hci0: opcode hci_req_add_ev 0x200e > Bluetooth: hci0: event 0x0e (sent = 0x00) > Bluetooth: hci0: event 0x3e (sent = 0x00) > Bluetooth: hci0: BT: subevent 0x0a (sent 0x00) > Bluetooth: __hci_cmd_sync_sk pending (event = 0x0a status=1, err=-110) > Bluetooth: hci0: Opcode 0x200d failed: -110 > Bluetooth: hci0: opcode 0x2006 plen 15 > Bluetooth: hci0: event 0x0e (sent = 0x00) > Bluetooth: hci0: opcode 0x200a plen 1 > Bluetooth: hci0: event 0x0e (sent = 0x00) > Bluetooth: hci0: request failed to create LE connection: err -110 > > > But now it times out as reported. It looks like the > intermittent hci_abort_conn() is at fault here. My theory is > that replacing hci->sent_cmd is the problem here, as other > events can't be matched anymore. Yep, unpair command uses hci_abort_conn when it should really be using hci_abort_conn_sync, the problem is if we do that then it probably no longer work because it would have to wait for sync queue to complete so it would only be able to disconnect after the connect command completes, well perhaps that is acceptable otherwise we need a different queue to handle command that abort/cancel other already in the queue. > We've been deploying the revert for a while now and I just posted > it to the mailing list[1]. There have been other reports > of this issue with different hardware too and fixing sent_cmd > would likely be too complicated/time intensive for me. > > I am happy to test future patches that fix this properly though. > > [1]: https://lore.kernel.org/linux-bluetooth/20220616092418.738877-1-a.fatoum@pengutronix.de/T/#t > > Cheers, > Ahmad > > > > > > > Cheers, > > Ahmad > > > > > -- > Pengutronix e.K. | | > Steuerwalder Str. 21 | http://www.pengutronix.de/ | > 31137 Hildesheim, Germany | Phone: +49-5121-206917-0 | > Amtsgericht Hildesheim, HRA 2686 | Fax: +49-5121-206917-5555 | -- Luiz Augusto von Dentz