From nobody Tue Apr 12 21:47:34 2022 X-Original-To: freebsd-hackers@mlmmj.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mlmmj.nyi.freebsd.org (Postfix) with ESMTP id E212C1AF7953 for ; Tue, 12 Apr 2022 21:47:38 +0000 (UTC) (envelope-from phk@critter.freebsd.dk) Received: from phk.freebsd.dk (phk.freebsd.dk [130.225.244.222]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 4KdK895p0qz4dY5 for ; Tue, 12 Apr 2022 21:47:37 +0000 (UTC) (envelope-from phk@critter.freebsd.dk) Received: from critter.freebsd.dk (unknown [192.168.55.3]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256) (No client certificate requested) by phk.freebsd.dk (Postfix) with ESMTPS id 68C4889284; Tue, 12 Apr 2022 21:47:30 +0000 (UTC) Received: from critter.freebsd.dk (localhost [127.0.0.1]) by critter.freebsd.dk (8.16.1/8.16.1) with ESMTPS id 23CLlZBC014615 (version=TLSv1.3 cipher=TLS_AES_256_GCM_SHA384 bits=256 verify=NO); Tue, 12 Apr 2022 21:47:35 GMT (envelope-from phk@critter.freebsd.dk) Received: (from phk@localhost) by critter.freebsd.dk (8.16.1/8.16.1/Submit) id 23CLlYjE014614; Tue, 12 Apr 2022 21:47:34 GMT (envelope-from phk) Message-Id: <202204122147.23CLlYjE014614@critter.freebsd.dk> To: mahesh mv cc: "freebsd-hackers@freebsd.org" Subject: Re: xhci USB transaction error and subsequent recovery mechanism on Freebsd stable/12 In-reply-to: <1524993805.98701.1649776236883@mail.yahoo.com> From: "Poul-Henning Kamp" References: <1524993805.98701.1649776236883.ref@mail.yahoo.com> <1524993805.98701.1649776236883@mail.yahoo.com> List-Id: Technical discussions relating to FreeBSD List-Archive: https://lists.freebsd.org/archives/freebsd-hackers List-Help: List-Post: List-Subscribe: List-Unsubscribe: Sender: owner-freebsd-hackers@freebsd.org MIME-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-ID: <14612.1649800054.1@critter.freebsd.dk> Content-Transfer-Encoding: quoted-printable Date: Tue, 12 Apr 2022 21:47:34 +0000 X-Rspamd-Queue-Id: 4KdK895p0qz4dY5 X-Spamd-Bar: -- Authentication-Results: mx1.freebsd.org; dkim=none; dmarc=none; spf=pass (mx1.freebsd.org: domain of phk@critter.freebsd.dk designates 130.225.244.222 as permitted sender) smtp.mailfrom=phk@critter.freebsd.dk X-Spamd-Result: default: False [-3.00 / 15.00]; TO_DN_EQ_ADDR_SOME(0.00)[]; ARC_NA(0.00)[]; FREEFALL_USER(0.00)[phk]; FROM_HAS_DN(0.00)[]; TO_DN_SOME(0.00)[]; R_SPF_ALLOW(-0.20)[+mx]; NEURAL_HAM_LONG(-1.00)[-1.000]; MIME_GOOD(-0.10)[text/plain]; DMARC_NA(0.00)[freebsd.dk]; NEURAL_HAM_MEDIUM(-1.00)[-1.000]; RCVD_COUNT_THREE(0.00)[3]; TO_MATCH_ENVRCPT_SOME(0.00)[]; MID_RHS_MATCH_FROMTLD(0.00)[]; NEURAL_HAM_SHORT(-1.00)[-0.997]; RCPT_COUNT_TWO(0.00)[2]; MLMMJ_DEST(0.00)[freebsd-hackers]; FREEMAIL_TO(0.00)[yahoo.com]; FORGED_SENDER(0.30)[phk@phk.freebsd.dk,phk@critter.freebsd.dk]; R_DKIM_NA(0.00)[]; MIME_TRACE(0.00)[0:+]; ASN(0.00)[asn:1835, ipnet:130.225.0.0/16, country:EU]; FROM_NEQ_ENVFROM(0.00)[phk@phk.freebsd.dk,phk@critter.freebsd.dk]; RCVD_TLS_ALL(0.00)[] X-ThisMailContainsUnwantedMimeParts: N -------- mahesh mv writes: > READ(10) errors. The READ(10) error recovers with in couple of retries m= ost > of the times but few cases we have observed that the read retries gets e= xhausted and [...] About once a week I see the same general phenomena on a RockPro64 running = 13.0-RELEASE-p6. After "usbconfig -d 5.7 reset" and "zpool clear" the ZFS mirror is back in= operation. The other drive in the mirror, (-d 5.4) never does this. This server has a twin ("keith") with different USB disks, never seen it t= here either. Despite spending a fair amount of time on it, I have never been able to find any hints of hardware trouble (ie: USB drive, USB cables or the industrial-grade powered USB-hub.) Usbconfig on the system in question: ugen0.1: at usbus0, cfg=3D0 md=3DHOST spd=3DHIGH = (480Mbps) pwr=3DSAVE (0mA) ugen2.1: at usbus2, cfg=3D0 md=3DHOST spd=3DHIGH = (480Mbps) pwr=3DSAVE (0mA) ugen1.1: at usbus1, cfg=3D0 md=3DHOST spd=3DFULL = (12Mbps) pwr=3DSAVE (0mA) ugen5.1: at usbus5, cfg=3D0 md=3DHOST spd=3DSUPE= R (5.0Gbps) pwr=3DSAVE (0mA) ugen4.1: at usbus4, cfg=3D0 md=3DHOST spd=3DSUPE= R (5.0Gbps) pwr=3DSAVE (0mA) ugen3.1: at usbus3, cfg=3D0 md=3DHOST spd=3DFULL = (12Mbps) pwr=3DSAVE (0mA) ugen5.2: at usbus5, cfg=3D0 md=3DHOST spd= =3DHIGH (480Mbps) pwr=3DSAVE (100mA) ugen5.3: at usbus5, cfg=3D0 md=3DHOST spd=3DFULL (12Mb= ps) pwr=3DON (90mA) ugen5.4: at usbus5, cfg=3D0 md=3DHOST spd=3DHIGH (480= Mbps) pwr=3DON (500mA) ugen5.5: at usbus5, cfg=3D0 md=3DHOST spd=3DFULL (= 12Mbps) pwr=3DON (300mA) ugen5.6: at usbus5, cfg=3D0 md=3DHOST spd=3DHI= GH (480Mbps) pwr=3DON (450mA) ugen5.7: at usbus5, cfg=3D0 md=3DHOST spd=3DHIGH (48= 0Mbps) pwr=3DON (500mA) Most recent event was yesterday: Apr 11 03:01:04 <0.2> mick kernel: (da1:umass-sim1:1:0:0): READ(10). CDB:= 28 00 08 42 8f 60 00 00 08 00 = Apr 11 03:01:04 <0.2> mick kernel: (da1:umass-sim1:1:0:0): CAM status: CC= B request completed with an error Apr 11 03:01:04 <0.2> mick kernel: (da1:umass-sim1:1:0:0): Retrying comma= nd, 3 more tries remain Apr 11 03:01:04 <0.2> mick kernel: (da1:umass-sim1:1:0:0): READ(10). CDB:= 28 00 08 42 8f 60 00 00 08 00 = Apr 11 03:01:04 <0.2> mick kernel: (da1:umass-sim1:1:0:0): CAM status: CC= B request completed with an error Apr 11 03:01:04 <0.2> mick kernel: (da1:umass-sim1:1:0:0): Retrying comma= nd, 2 more tries remain Apr 11 03:01:05 <0.2> mick kernel: (da1:umass-sim1:1:0:0): READ(10). CDB:= 28 00 08 42 8f 60 00 00 08 00 = Apr 11 03:01:05 <0.2> mick kernel: (da1:umass-sim1:1:0:0): CAM status: CC= B request completed with an error Apr 11 03:01:05 <0.2> mick kernel: (da1:umass-sim1:1:0:0): Retrying comma= nd, 1 more tries remain Apr 11 03:01:05 <0.2> mick kernel: (da1:umass-sim1:1:0:0): READ(10). CDB:= 28 00 08 42 8f 60 00 00 08 00 = Apr 11 03:01:05 <0.2> mick kernel: (da1:umass-sim1:1:0:0): CAM status: CC= B request completed with an error Apr 11 03:01:05 <0.2> mick kernel: (da1:umass-sim1:1:0:0): Retrying comma= nd, 0 more tries remain Apr 11 03:01:06 <0.2> mick kernel: (da1:umass-sim1:1:0:0): READ(10). CDB:= 28 00 08 42 8f 60 00 00 08 00 = Apr 11 03:01:06 <0.2> mick kernel: (da1:umass-sim1:1:0:0): CAM status: CC= B request completed with an error Apr 11 03:01:06 <0.2> mick kernel: (da1:umass-sim1:1:0:0): Error 5, Retri= es exhausted Apr 11 03:01:06 <0.2> mick kernel: (da1:umass-sim1:1:0:0): READ(10). CDB:= 28 00 00 00 02 10 00 00 10 00 = Apr 11 03:01:06 <0.2> mick kernel: (da1:umass-sim1:1:0:0): CAM status: CC= B request completed with an error Apr 11 03:01:06 <0.2> mick kernel: (da1:umass-sim1:1:0:0): Retrying comma= nd, 3 more tries remain Apr 11 03:01:07 <0.2> mick kernel: (da1:umass-sim1:1:0:0): READ(10). CDB:= 28 00 00 00 02 10 00 00 10 00 = Apr 11 03:01:07 <0.2> mick kernel: (da1:umass-sim1:1:0:0): CAM status: CC= B request completed with an error Apr 11 03:01:07 <0.2> mick kernel: (da1:umass-sim1:1:0:0): Retrying comma= nd, 2 more tries remain Apr 11 03:01:07 <0.2> mick kernel: (da1:umass-sim1:1:0:0): READ(10). CDB:= 28 00 00 00 02 10 00 00 10 00 = Apr 11 03:01:07 <0.2> mick kernel: (da1:umass-sim1:1:0:0): CAM status: CC= B request completed with an error Apr 11 03:01:07 <0.2> mick kernel: (da1:umass-sim1:1:0:0): Retrying comma= nd, 1 more tries remain Apr 11 03:01:08 <0.2> mick kernel: (da1:umass-sim1:1:0:0): READ(10). CDB:= 28 00 00 00 02 10 00 00 10 00 = Apr 11 03:01:08 <0.2> mick kernel: (da1:umass-sim1:1:0:0): CAM status: CC= B request completed with an error Apr 11 03:01:08 <0.2> mick kernel: (da1:umass-sim1:1:0:0): Retrying comma= nd, 0 more tries remain Apr 11 03:01:08 <0.2> mick kernel: (da1:umass-sim1:1:0:0): READ(10). CDB:= 28 00 00 00 02 10 00 00 10 00 = Apr 11 03:01:08 <0.2> mick kernel: (da1:umass-sim1:1:0:0): CAM status: CC= B request completed with an error Apr 11 03:01:08 <0.2> mick kernel: (da1:umass-sim1:1:0:0): Error 5, Retri= es exhausted Apr 11 03:01:09 <23.4> mick ZFS[48383]: vdev I/O failure, zpool=3Dmick pa= th=3D/dev/da1 offset=3D4000786423808 size=3D8192 error=3D5 Apr 11 03:01:09 <23.4> mick ZFS[48387]: vdev I/O failure, zpool=3Dmick pa= th=3D/dev/da1 offset=3D4000786685952 size=3D8192 error=3D5 Apr 11 03:01:09 <23.4> mick ZFS[48391]: vdev I/O failure, zpool=3Dmick pa= th=3D/dev/da1 offset=3D270336 size=3D8192 error=3D5 Apr 11 03:01:09 <23.3> mick ZFS[48395]: vdev probe failure, zpool=3Dmick = path=3D/dev/da1 Apr 11 03:01:09 <0.2> mick kernel: (da1:umass-sim1:1:0:0): READ(10). CDB:= 28 00 00 00 02 10 00 00 10 00 = Apr 11 03:01:09 <0.2> mick kernel: (da1:umass-sim1:1:0:0): CAM status: CC= B request completed with an error Apr 11 03:01:09 <0.2> mick kernel: (da1:umass-sim1:1:0:0): Retrying comma= nd, 3 more tries remain Apr 11 03:01:10 <0.2> mick kernel: (da1:umass-sim1:1:0:0): READ(10). CDB:= 28 00 00 00 02 10 00 00 10 00 = Apr 11 03:01:10 <0.2> mick kernel: (da1:umass-sim1:1:0:0): CAM status: CC= B request completed with an error Apr 11 03:01:10 <0.2> mick kernel: (da1:umass-sim1:1:0:0): Retrying comma= nd, 2 more tries remain Apr 11 03:01:10 <0.2> mick kernel: (da1:umass-sim1:1:0:0): READ(10). CDB:= 28 00 00 00 02 10 00 00 10 00 = Apr 11 03:01:10 <0.2> mick kernel: (da1:umass-sim1:1:0:0): CAM status: CC= B request completed with an error Apr 11 03:01:10 <0.2> mick kernel: (da1:umass-sim1:1:0:0): Retrying comma= nd, 1 more tries remain Apr 11 03:01:11 <0.2> mick kernel: (da1:umass-sim1:1:0:0): READ(10). CDB:= 28 00 00 00 02 10 00 00 10 00 = Apr 11 03:01:11 <0.2> mick kernel: (da1:umass-sim1:1:0:0): CAM status: CC= B request completed with an error Apr 11 03:01:11 <0.2> mick kernel: (da1:umass-sim1:1:0:0): Retrying comma= nd, 0 more tries remain Apr 11 03:01:11 <0.2> mick kernel: (da1:umass-sim1:1:0:0): READ(10). CDB:= 28 00 00 00 02 10 00 00 10 00 = Apr 11 03:01:11 <0.2> mick kernel: (da1:umass-sim1:1:0:0): CAM status: CC= B request completed with an error Apr 11 03:01:11 <0.2> mick kernel: (da1:umass-sim1:1:0:0): Error 5, Retri= es exhausted Apr 11 03:01:11 <23.3> mick ZFS[48399]: vdev probe failure, zpool=3Dmick = path=3D/dev/da1 Apr 11 03:01:11 <23.5> mick ZFS[48403]: vdev state changed, pool_guid=3D7= 854867548980906247 vdev_guid=3D14874313982910104056 Apr 11 03:01:16 <0.2> mick kernel: (da1:umass-sim1:1:0:0): got CAM status= 0x44 Apr 11 03:01:16 <0.2> mick kernel: (da1:umass-sim1:1:0:0): fatal error, f= ailed to attach to device Apr 11 03:01:16 <0.2> mick kernel: da1 at umass-sim1 bus 1 scbus1 target = 0 lun 0 Apr 11 03:01:16 <0.2> mick kernel: da1: s/n 00= 00NL6AE1LV detached Apr 11 03:01:16 <0.2> mick kernel: (da1:umass-sim1:1:0:0): Periph destroy= ed Poul-Henning PS: "completed with an error" without any details about the error is not v= ery helpful for debugging... -- = Poul-Henning Kamp | UNIX since Zilog Zeus 3.20 phk@FreeBSD.ORG | TCP/IP since RFC 956 FreeBSD committer | BSD since 4.3-tahoe = Never attribute to malice what can adequately be explained by incompetence= .