VUSBUrbTrace.cpp@ 91881

Last change on this file since 91881 was 91374, checked in by vboxsync, 3 years ago
Devices/USB: vusbUrbTrace() can dereference a NULL pUrb->pVUsb->pDev->pUsbIns in Log() when restoring a VM from the 'Saved' or 'AbortedSaved' state.
Property svn:eol-style set to `native` Property svn:keywords set to `Author Date Id Revision`
File size: 36.4 KB

Line
1	/* $Id: VUSBUrbTrace.cpp 91374 2021-09-24 17:40:30Z vboxsync $ */
2	/** @file
3	* Virtual USB - URBs.
4	*/
5
6	/*
7	* Copyright (C) 2006-2020 Oracle Corporation
8	*
9	* This file is part of VirtualBox Open Source Edition (OSE), as
10	* available from http://www.virtualbox.org. This file is free software;
11	* you can redistribute it and/or modify it under the terms of the GNU
12	* General Public License (GPL) as published by the Free Software
13	* Foundation, in version 2 as it comes in the "COPYING" file of the
14	* VirtualBox OSE distribution. VirtualBox OSE is distributed in the
15	* hope that it will be useful, but WITHOUT ANY WARRANTY of any kind.
16	*/
17
18
19	/*********************************************************************************************************************************
20	* Header Files *
21	*********************************************************************************************************************************/
22	#define LOG_GROUP LOG_GROUP_DRV_VUSB
23	#include <VBox/vmm/pdm.h>
24	#include <VBox/vmm/vmapi.h>
25	#include <iprt/errcore.h>
26	#include <iprt/alloc.h>
27	#include <VBox/log.h>
28	#include <iprt/time.h>
29	#include <iprt/thread.h>
30	#include <iprt/semaphore.h>
31	#include <iprt/string.h>
32	#include <iprt/assert.h>
33	#include <iprt/asm.h>
34	#include <iprt/env.h>
35	#include "VUSBInternal.h"
36
37
38
39	#ifdef LOG_ENABLED
40	DECLINLINE(const char *) GetScsiErrCd(uint8_t ScsiErr)
41	{
42	switch (ScsiErr)
43	{
44	case 0: return "?";
45	}
46	return "?";
47	}
48
49	DECLINLINE(const char *) GetScsiKCQ(uint8_t Key, uint8_t ASC, uint8_t ASCQ)
50	{
51	switch (Key)
52	{
53	case 0:
54	switch (RT_MAKE_U16(ASC, ASCQ))
55	{
56	case RT_MAKE_U16(0x00, 0x00): return "No error";
57	}
58	break;
59
60	case 1:
61	return "Soft Error";
62
63	case 2:
64	return "Not Ready";
65
66	case 3:
67	return "Medium Error";
68
69	case 4:
70	return "Hard Error";
71
72	case 5:
73	return "Illegal Request";
74
75	case 6:
76	return "Unit Attention";
77
78	case 7:
79	return "Write Protected";
80
81	case 0xb:
82	return "Aborted Command";
83	}
84	return "?";
85	}
86
87	DECLHIDDEN(const char *) vusbUrbStatusName(VUSBSTATUS enmStatus)
88	{
89	/** Strings for the URB statuses. */
90	static const char * const s_apszNames[] =
91	{
92	"OK",
93	"STALL",
94	"ERR_DNR",
95	"ERR_CRC",
96	"DATA_UNDERRUN",
97	"DATA_OVERRUN",
98	"NOT_ACCESSED",
99	"7", "8", "9", "10", "11", "12", "13", "14", "15"
100	};
101
102	return enmStatus < (int)RT_ELEMENTS(s_apszNames)
103	? s_apszNames[enmStatus]
104	: enmStatus == VUSBSTATUS_INVALID
105	? "INVALID"
106	: "??";
107	}
108
109	DECLHIDDEN(const char *) vusbUrbDirName(VUSBDIRECTION enmDir)
110	{
111	/** Strings for the URB directions. */
112	static const char * const s_apszNames[] =
113	{
114	"setup",
115	"in",
116	"out"
117	};
118
119	return enmDir < (int)RT_ELEMENTS(s_apszNames)
120	? s_apszNames[enmDir]
121	: "??";
122	}
123
124	DECLHIDDEN(const char *) vusbUrbTypeName(VUSBXFERTYPE enmType)
125	{
126	/** Strings for the URB types. */
127	static const char * const s_apszName[] =
128	{
129	"control-part",
130	"isochronous",
131	"bulk",
132	"interrupt",
133	"control"
134	};
135
136	return enmType < (int)RT_ELEMENTS(s_apszName)
137	? s_apszName[enmType]
138	: "??";
139	}
140
141	/**
142	* Logs an URB.
143	*
144	* Note that pUrb->pVUsb->pDev and pUrb->pVUsb->pDev->pUsbIns can all be NULL.
145	*/
146	DECLHIDDEN(void) vusbUrbTrace(PVUSBURB pUrb, const char *pszMsg, bool fComplete)
147	{
148	PVUSBDEV pDev = pUrb->pVUsb ? pUrb->pVUsb->pDev : NULL; /* Can be NULL when called from usbProxyConstruct and friends. */
149	PVUSBPIPE pPipe = &pDev->aPipes[pUrb->EndPt];
150	const uint8_t *pbData = pUrb->abData;
151	uint32_t cbData = pUrb->cbData;
152	PCVUSBSETUP pSetup = NULL;
153	bool fDescriptors = false;
154	static size_t s_cchMaxMsg = 10;
155	size_t cchMsg = strlen(pszMsg);
156	if (cchMsg > s_cchMaxMsg)
157	s_cchMaxMsg = cchMsg;
158
159	Log(("%s: %*s: pDev=%p[%s] rc=%s a=%i e=%u d=%s t=%s cb=%#x(%d) ts=%RU64 (%RU64 ns ago) %s\n",
160	pUrb->pszDesc, s_cchMaxMsg, pszMsg,
161	pDev,
162	pUrb->pVUsb && pUrb->pVUsb->pDev && pUrb->pVUsb->pDev->pUsbIns ? pUrb->pVUsb->pDev->pUsbIns->pszName : "",
163	vusbUrbStatusName(pUrb->enmStatus),
164	pDev ? pDev->u8Address : -1,
165	pUrb->EndPt,
166	vusbUrbDirName(pUrb->enmDir),
167	vusbUrbTypeName(pUrb->enmType),
168	pUrb->cbData,
169	pUrb->cbData,
170	pUrb->pVUsb ? pUrb->pVUsb->u64SubmitTS : 0,
171	pUrb->pVUsb ? RTTimeNanoTS() - pUrb->pVUsb->u64SubmitTS : 0,
172	pUrb->fShortNotOk ? "ShortNotOk" : "ShortOk"));
173
174	#ifndef DEBUG_bird
175	if ( pUrb->enmType == VUSBXFERTYPE_CTRL
176	&& pUrb->enmStatus == VUSBSTATUS_OK)
177	return;
178	#endif
179
180	if ( pUrb->enmType == VUSBXFERTYPE_MSG
181	\|\| ( pUrb->enmDir == VUSBDIRECTION_SETUP
182	&& pUrb->enmType == VUSBXFERTYPE_CTRL
183	&& cbData))
184	{
185	static const char * const s_apszReqDirs[] = {"host2dev", "dev2host"};
186	static const char * const s_apszReqTypes[] = {"std", "class", "vendor", "reserved"};
187	static const char * const s_apszReqRecipients[] = {"dev", "if", "endpoint", "other"};
188	static const char * const s_apszRequests[] =
189	{
190	"GET_STATUS", "CLEAR_FEATURE", "2?", "SET_FEATURE",
191	"4?", "SET_ADDRESS", "GET_DESCRIPTOR", "SET_DESCRIPTOR",
192	"GET_CONFIGURATION", "SET_CONFIGURATION", "GET_INTERFACE", "SET_INTERFACE",
193	"SYNCH_FRAME"
194	};
195	pSetup = (PVUSBSETUP)pUrb->abData;
196	pbData += sizeof(*pSetup);
197	cbData -= sizeof(*pSetup);
198
199	Log(("%s: %*s: CTRL: bmRequestType=0x%.2x (%s %s %s) bRequest=0x%.2x (%s) wValue=0x%.4x wIndex=0x%.4x wLength=0x%.4x\n",
200	pUrb->pszDesc, s_cchMaxMsg, pszMsg,
201	pSetup->bmRequestType, s_apszReqDirs[pSetup->bmRequestType >> 7], s_apszReqTypes[(pSetup->bmRequestType >> 5) & 0x3],
202	(unsigned)(pSetup->bmRequestType & 0xf) < RT_ELEMENTS(s_apszReqRecipients) ? s_apszReqRecipients[pSetup->bmRequestType & 0xf] : "??",
203	pSetup->bRequest, pSetup->bRequest < RT_ELEMENTS(s_apszRequests) ? s_apszRequests[pSetup->bRequest] : "??",
204	pSetup->wValue, pSetup->wIndex, pSetup->wLength));
205
206	if ( pSetup->bRequest == VUSB_REQ_GET_DESCRIPTOR
207	&& fComplete
208	&& pUrb->enmStatus == VUSBSTATUS_OK
209	&& ((pSetup->bmRequestType >> 5) & 0x3) < 2 /* vendor */)
210	fDescriptors = true;
211	}
212	else if ( fComplete
213	&& pUrb->enmDir == VUSBDIRECTION_IN
214	&& pUrb->enmType == VUSBXFERTYPE_CTRL
215	&& pUrb->enmStatus == VUSBSTATUS_OK
216	&& pPipe->pCtrl
217	&& pPipe->pCtrl->enmStage == CTLSTAGE_DATA
218	&& cbData > 0)
219	{
220	pSetup = pPipe->pCtrl->pMsg;
221	if (pSetup->bRequest == VUSB_REQ_GET_DESCRIPTOR)
222	{
223	/* HID report (0x22) and physical (0x23) descriptors do not use standard format
224	* with descriptor length/type at the front. Don't try to dump them, we'll only
225	* misinterpret them.
226	*/
227	if ( ((pSetup->bmRequestType >> 5) & 0x3) == 1 /* class */
228	&& ((RT_HIBYTE(pSetup->wValue) == 0x22) \|\| (RT_HIBYTE(pSetup->wValue) == 0x23)))
229	{
230	fDescriptors = false;
231	}
232	}
233	else
234	fDescriptors = true;
235	}
236
237	/*
238	* Dump descriptors.
239	*/
240	if (fDescriptors)
241	{
242	const uint8_t *pb = pbData;
243	const uint8_t *pbEnd = pbData + cbData;
244	while (pb + 1 < pbEnd)
245	{
246	const unsigned cbLeft = pbEnd - pb;
247	const unsigned cbLength = *pb;
248	unsigned cb = cbLength;
249	uint8_t bDescriptorType = pb[1];
250
251	/* length out of bounds? */
252	if (cbLength > cbLeft)
253	{
254	cb = cbLeft;
255	if (cbLength != 0xff) /* ignore this */
256	Log(("URB: %*s: DESC: warning descriptor length goes beyond the end of the URB! cbLength=%d cbLeft=%d\n",
257	s_cchMaxMsg, pszMsg, cbLength, cbLeft));
258	}
259
260	if (cb >= 2)
261	{
262	Log(("URB: %*s: DESC: %04x: %25s = %#04x (%d)\n"
263	"URB: %*s: %04x: %25s = %#04x (",
264	s_cchMaxMsg, pszMsg, pb - pbData, "bLength", cbLength, cbLength,
265	s_cchMaxMsg, pszMsg, pb - pbData + 1, "bDescriptorType", bDescriptorType));
266
267	#pragma pack(1)
268	#define BYTE_FIELD(strct, memb) \
269	if ((unsigned)RT_OFFSETOF(strct, memb) < cb) \
270	Log(("URB: %*s: %04x: %25s = %#04x\n", s_cchMaxMsg, pszMsg, \
271	pb + RT_OFFSETOF(strct, memb) - pbData, #memb, pb[RT_OFFSETOF(strct, memb)]))
272	#define BYTE_FIELD_START(strct, memb) do { \
273	if ((unsigned)RT_OFFSETOF(strct, memb) < cb) \
274	{ \
275	Log(("URB: %*s: %04x: %25s = %#04x", s_cchMaxMsg, pszMsg, \
276	pb + RT_OFFSETOF(strct, memb) - pbData, #memb, pb[RT_OFFSETOF(strct, memb)]))
277	#define BYTE_FIELD_END(strct, memb) \
278	Log(("\n")); \
279	} } while (0)
280	#define WORD_FIELD(strct, memb) \
281	if ((unsigned)RT_OFFSETOF(strct, memb) + 1 < cb) \
282	Log(("URB: %*s: %04x: %25s = %#06x\n", s_cchMaxMsg, pszMsg, \
283	pb + RT_OFFSETOF(strct, memb) - pbData, #memb, (uint16_t )&pb[RT_OFFSETOF(strct, memb)]))
284	#define BCD_FIELD(strct, memb) \
285	if ((unsigned)RT_OFFSETOF(strct, memb) + 1 < cb) \
286	Log(("URB: %*s: %04x: %25s = %#06x (%02x.%02x)\n", s_cchMaxMsg, pszMsg, \
287	pb + RT_OFFSETOF(strct, memb) - pbData, #memb, (uint16_t )&pb[RT_OFFSETOF(strct, memb)], \
288	pb[RT_OFFSETOF(strct, memb) + 1], pb[RT_OFFSETOF(strct, memb)]))
289	#define SIZE_CHECK(strct) \
290	if (cb > sizeof(strct)) \
291	Log(("URB: %s: %04x: WARNING %d extra byte(s) %.Rhxs\n", s_cchMaxMsg, pszMsg, \
292	pb + sizeof(strct) - pbData, cb - sizeof(strct), cb - sizeof(strct), pb + sizeof(strct))); \
293	else if (cb < sizeof(strct)) \
294	Log(("URB: %*s: %04x: WARNING %d missing byte(s)! Expected size %d.\n", s_cchMaxMsg, pszMsg, \
295	pb + cb - pbData, sizeof(strct) - cb, sizeof(strct)))
296
297	/* on type */
298	switch (bDescriptorType)
299	{
300	case VUSB_DT_DEVICE:
301	{
302	struct dev_desc
303	{
304	uint8_t bLength;
305	uint8_t bDescriptorType;
306	uint16_t bcdUSB;
307	uint8_t bDeviceClass;
308	uint8_t bDeviceSubClass;
309	uint8_t bDeviceProtocol;
310	uint8_t bMaxPacketSize0;
311	uint16_t idVendor;
312	uint16_t idProduct;
313	uint16_t bcdDevice;
314	uint8_t iManufacturer;
315	uint8_t iProduct;
316	uint8_t iSerialNumber;
317	uint8_t bNumConfigurations;
318	} pDesc = (struct dev_desc )pb; NOREF(pDesc);
319	Log(("DEV)\n"));
320	BCD_FIELD( struct dev_desc, bcdUSB);
321	BYTE_FIELD(struct dev_desc, bDeviceClass);
322	BYTE_FIELD(struct dev_desc, bDeviceSubClass);
323	BYTE_FIELD(struct dev_desc, bDeviceProtocol);
324	BYTE_FIELD(struct dev_desc, bMaxPacketSize0);
325	WORD_FIELD(struct dev_desc, idVendor);
326	WORD_FIELD(struct dev_desc, idProduct);
327	BCD_FIELD( struct dev_desc, bcdDevice);
328	BYTE_FIELD(struct dev_desc, iManufacturer);
329	BYTE_FIELD(struct dev_desc, iProduct);
330	BYTE_FIELD(struct dev_desc, iSerialNumber);
331	BYTE_FIELD(struct dev_desc, bNumConfigurations);
332	SIZE_CHECK(struct dev_desc);
333	break;
334	}
335
336	case VUSB_DT_CONFIG:
337	{
338	struct cfg_desc
339	{
340	uint8_t bLength;
341	uint8_t bDescriptorType;
342	uint16_t wTotalLength;
343	uint8_t bNumInterfaces;
344	uint8_t bConfigurationValue;
345	uint8_t iConfiguration;
346	uint8_t bmAttributes;
347	uint8_t MaxPower;
348	} pDesc = (struct cfg_desc )pb; NOREF(pDesc);
349	Log(("CFG)\n"));
350	WORD_FIELD(struct cfg_desc, wTotalLength);
351	BYTE_FIELD(struct cfg_desc, bNumInterfaces);
352	BYTE_FIELD(struct cfg_desc, bConfigurationValue);
353	BYTE_FIELD(struct cfg_desc, iConfiguration);
354	BYTE_FIELD_START(struct cfg_desc, bmAttributes);
355	static const char * const s_apszTransType[4] = { "Control", "Isochronous", "Bulk", "Interrupt" };
356	static const char * const s_apszSyncType[4] = { "NoSync", "Asynchronous", "Adaptive", "Synchronous" };
357	static const char * const s_apszUsageType[4] = { "Data ep", "Feedback ep.", "Implicit feedback Data ep.", "Reserved" };
358	Log((" %s - %s - %s", s_apszTransType[(pDesc->bmAttributes & 0x3)],
359	s_apszSyncType[((pDesc->bmAttributes >> 2) & 0x3)], s_apszUsageType[((pDesc->bmAttributes >> 4) & 0x3)]));
360	BYTE_FIELD_END(struct cfg_desc, bmAttributes);
361	BYTE_FIELD(struct cfg_desc, MaxPower);
362	SIZE_CHECK(struct cfg_desc);
363	break;
364	}
365
366	case VUSB_DT_STRING:
367	if (!pSetup->wIndex)
368	{
369	/* langid array */
370	uint16_t pu16 = (uint16_t )pb + 1;
371	Log(("LANGIDs)\n"));
372	while ((uintptr_t)pu16 + 2 - (uintptr_t)pb <= cb)
373	{
374	Log(("URB: %*s: %04x: wLANGID[%#x] = %#06x\n",
375	s_cchMaxMsg, pszMsg, (uint8_t )pu16 - pbData, pu16 - (uint16_t )pb, *pu16));
376	pu16++;
377	}
378	if (cb & 1)
379	Log(("URB: %*s: %04x: WARNING descriptor size is odd! extra byte: %02\n",
380	s_cchMaxMsg, pszMsg, (uint8_t )pu16 - pbData, (uint8_t *)pu16));
381	}
382	else
383	{
384	/** a string. */
385	Log(("STRING)\n"));
386	if (cb > 2)
387	Log(("URB: %s: %04x: Length=%d String=%.ls\n",
388	s_cchMaxMsg, pszMsg, pb - pbData, cb - 2, cb / 2 - 1, pb + 2));
389	else
390	Log(("URB: %*s: %04x: Length=0\n", s_cchMaxMsg, pszMsg, pb - pbData));
391	}
392	break;
393
394	case VUSB_DT_INTERFACE:
395	{
396	struct if_desc
397	{
398	uint8_t bLength;
399	uint8_t bDescriptorType;
400	uint8_t bInterfaceNumber;
401	uint8_t bAlternateSetting;
402	uint8_t bNumEndpoints;
403	uint8_t bInterfaceClass;
404	uint8_t bInterfaceSubClass;
405	uint8_t bInterfaceProtocol;
406	uint8_t iInterface;
407	} pDesc = (struct if_desc )pb; NOREF(pDesc);
408	Log(("IF)\n"));
409	BYTE_FIELD(struct if_desc, bInterfaceNumber);
410	BYTE_FIELD(struct if_desc, bAlternateSetting);
411	BYTE_FIELD(struct if_desc, bNumEndpoints);
412	BYTE_FIELD(struct if_desc, bInterfaceClass);
413	BYTE_FIELD(struct if_desc, bInterfaceSubClass);
414	BYTE_FIELD(struct if_desc, bInterfaceProtocol);
415	BYTE_FIELD(struct if_desc, iInterface);
416	SIZE_CHECK(struct if_desc);
417	break;
418	}
419
420	case VUSB_DT_ENDPOINT:
421	{
422	struct ep_desc
423	{
424	uint8_t bLength;
425	uint8_t bDescriptorType;
426	uint8_t bEndpointAddress;
427	uint8_t bmAttributes;
428	uint16_t wMaxPacketSize;
429	uint8_t bInterval;
430	} pDesc = (struct ep_desc )pb; NOREF(pDesc);
431	Log(("EP)\n"));
432	BYTE_FIELD(struct ep_desc, bEndpointAddress);
433	BYTE_FIELD(struct ep_desc, bmAttributes);
434	WORD_FIELD(struct ep_desc, wMaxPacketSize);
435	BYTE_FIELD(struct ep_desc, bInterval);
436	SIZE_CHECK(struct ep_desc);
437	break;
438	}
439
440	case VUSB_DT_DEVICE_QUALIFIER:
441	{
442	struct dq_desc
443	{
444	uint8_t bLength;
445	uint8_t bDescriptorType;
446	uint16_t bcdUSB;
447	uint8_t bDeviceClass;
448	uint8_t bDeviceSubClass;
449	uint8_t bDeviceProtocol;
450	uint8_t bMaxPacketSize0;
451	uint8_t bNumConfigurations;
452	uint8_t bReserved;
453	} pDQDesc = (struct dq_desc )pb; NOREF(pDQDesc);
454	Log(("DEVQ)\n"));
455	BCD_FIELD( struct dq_desc, bcdUSB);
456	BYTE_FIELD(struct dq_desc, bDeviceClass);
457	BYTE_FIELD(struct dq_desc, bDeviceSubClass);
458	BYTE_FIELD(struct dq_desc, bDeviceProtocol);
459	BYTE_FIELD(struct dq_desc, bMaxPacketSize0);
460	BYTE_FIELD(struct dq_desc, bNumConfigurations);
461	BYTE_FIELD(struct dq_desc, bReserved);
462	SIZE_CHECK(struct dq_desc);
463	break;
464	}
465
466	case VUSB_DT_OTHER_SPEED_CFG:
467	{
468	struct oth_cfg_desc
469	{
470	uint8_t bLength;
471	uint8_t bDescriptorType;
472	uint16_t wTotalLength;
473	uint8_t bNumInterfaces;
474	uint8_t bConfigurationValue;
475	uint8_t iConfiguration;
476	uint8_t bmAttributes;
477	uint8_t MaxPower;
478	} pDesc = (struct oth_cfg_desc )pb; NOREF(pDesc);
479	Log(("OCFG)\n"));
480	WORD_FIELD(struct oth_cfg_desc, wTotalLength);
481	BYTE_FIELD(struct oth_cfg_desc, bNumInterfaces);
482	BYTE_FIELD(struct oth_cfg_desc, bConfigurationValue);
483	BYTE_FIELD(struct oth_cfg_desc, iConfiguration);
484	BYTE_FIELD_START(struct oth_cfg_desc, bmAttributes);
485	static const char * const s_apszTransType[4] = { "Control", "Isochronous", "Bulk", "Interrupt" };
486	static const char * const s_apszSyncType[4] = { "NoSync", "Asynchronous", "Adaptive", "Synchronous" };
487	static const char * const s_apszUsageType[4] = { "Data ep", "Feedback ep.", "Implicit feedback Data ep.", "Reserved" };
488	Log((" %s - %s - %s", s_apszTransType[(pDesc->bmAttributes & 0x3)],
489	s_apszSyncType[((pDesc->bmAttributes >> 2) & 0x3)], s_apszUsageType[((pDesc->bmAttributes >> 4) & 0x3)]));
490	BYTE_FIELD_END(struct oth_cfg_desc, bmAttributes);
491	BYTE_FIELD(struct oth_cfg_desc, MaxPower);
492	SIZE_CHECK(struct oth_cfg_desc);
493	break;
494	}
495
496	case 0x21:
497	{
498	struct hid_desc
499	{
500	uint8_t bLength;
501	uint8_t bDescriptorType;
502	uint16_t bcdHid;
503	uint8_t bCountry;
504	uint8_t bNumDescriptors;
505	uint8_t bReportType;
506	uint16_t wReportLength;
507	} pDesc = (struct hid_desc )pb; NOREF(pDesc);
508	Log(("EP)\n"));
509	BCD_FIELD( struct hid_desc, bcdHid);
510	BYTE_FIELD(struct hid_desc, bCountry);
511	BYTE_FIELD(struct hid_desc, bNumDescriptors);
512	BYTE_FIELD(struct hid_desc, bReportType);
513	WORD_FIELD(struct hid_desc, wReportLength);
514	SIZE_CHECK(struct hid_desc);
515	break;
516	}
517
518	case 0xff:
519	Log(("UNKNOWN-ignore)\n"));
520	break;
521
522	default:
523	Log(("UNKNOWN)!!!\n"));
524	break;
525	}
526
527	#undef BYTE_FIELD
528	#undef WORD_FIELD
529	#undef BCD_FIELD
530	#undef SIZE_CHECK
531	#pragma pack()
532	}
533	else
534	{
535	Log(("URB: %*s: DESC: %04x: bLength=%d bDescriptorType=%d - invalid length\n",
536	s_cchMaxMsg, pszMsg, pb - pbData, cb, bDescriptorType));
537	break;
538	}
539
540	/* next */
541	pb += cb;
542	}
543	}
544
545	/*
546	* SCSI
547	*/
548	if ( pUrb->enmType == VUSBXFERTYPE_BULK
549	&& pUrb->enmDir == VUSBDIRECTION_OUT
550	&& pUrb->cbData >= 12
551	&& !memcmp(pUrb->abData, "USBC", 4))
552	{
553	const struct usbc
554	{
555	uint32_t Signature;
556	uint32_t Tag;
557	uint32_t DataTransferLength;
558	uint8_t Flags;
559	uint8_t Lun;
560	uint8_t Length;
561	uint8_t CDB[13];
562	} pUsbC = (struct usbc )pUrb->abData;
563	Log(("URB: %s: SCSI: Tag=%#x DataTransferLength=%#x Flags=%#x Lun=%#x Length=%#x CDB=%.Rhxs\n",
564	s_cchMaxMsg, pszMsg, pUsbC->Tag, pUsbC->DataTransferLength, pUsbC->Flags, pUsbC->Lun,
565	pUsbC->Length, pUsbC->Length, pUsbC->CDB));
566	const uint8_t *pb = &pUsbC->CDB[0];
567	switch (pb[0])
568	{
569	case 0x00: /* test unit read */
570	Log(("URB: %*s: SCSI: TEST_UNIT_READY LUN=%d Ctrl=%#RX8\n",
571	s_cchMaxMsg, pszMsg, pb[1] >> 5, pb[5]));
572	break;
573	case 0x03: /* Request Sense command */
574	Log(("URB: %*s: SCSI: REQUEST_SENSE LUN=%d AlcLen=%#RX16 Ctrl=%#RX8\n",
575	s_cchMaxMsg, pszMsg, pb[1] >> 5, pb[4], pb[5]));
576	break;
577	case 0x12: /* Inquiry command. */
578	Log(("URB: %*s: SCSI: INQUIRY EVPD=%d LUN=%d PgCd=%#RX8 AlcLen=%#RX8 Ctrl=%#RX8\n",
579	s_cchMaxMsg, pszMsg, pb[1] & 1, pb[1] >> 5, pb[2], pb[4], pb[5]));
580	break;
581	case 0x1a: /* Mode Sense(6) command */
582	Log(("URB: %*s: SCSI: MODE_SENSE6 LUN=%d DBD=%d PC=%d PgCd=%#RX8 AlcLen=%#RX8 Ctrl=%#RX8\n",
583	s_cchMaxMsg, pszMsg, pb[1] >> 5, !!(pb[1] & RT_BIT(3)), pb[2] >> 6, pb[2] & 0x3f, pb[4], pb[5]));
584	break;
585	case 0x5a:
586	Log(("URB: %*s: SCSI: MODE_SENSE10 LUN=%d DBD=%d PC=%d PgCd=%#RX8 AlcLen=%#RX16 Ctrl=%#RX8\n",
587	s_cchMaxMsg, pszMsg, pb[1] >> 5, !!(pb[1] & RT_BIT(3)), pb[2] >> 6, pb[2] & 0x3f,
588	RT_MAKE_U16(pb[8], pb[7]), pb[9]));
589	break;
590	case 0x25: /* Read Capacity(6) command. */
591	Log(("URB: %*s: SCSI: READ_CAPACITY\n",
592	s_cchMaxMsg, pszMsg));
593	break;
594	case 0x28: /* Read(10) command. */
595	Log(("URB: %*s: SCSI: READ10 RelAdr=%d FUA=%d DPO=%d LUN=%d LBA=%#RX32 Len=%#RX16 Ctrl=%#RX8\n",
596	s_cchMaxMsg, pszMsg,
597	pb[1] & 1, !!(pb[1] & RT_BIT(3)), !!(pb[1] & RT_BIT(4)), pb[1] >> 5,
598	RT_MAKE_U32_FROM_U8(pb[5], pb[4], pb[3], pb[2]),
599	RT_MAKE_U16(pb[8], pb[7]), pb[9]));
600	break;
601	case 0xa8: /* Read(12) command. */
602	Log(("URB: %*s: SCSI: READ12 RelAdr=%d FUA=%d DPO=%d LUN=%d LBA=%#RX32 Len=%#RX32 Ctrl=%#RX8\n",
603	s_cchMaxMsg, pszMsg,
604	pb[1] & 1, !!(pb[1] & RT_BIT(3)), !!(pb[1] & RT_BIT(4)), pb[1] >> 5,
605	RT_MAKE_U32_FROM_U8(pb[5], pb[4], pb[3], pb[2]),
606	RT_MAKE_U32_FROM_U8(pb[9], pb[8], pb[7], pb[6]),
607	pb[11]));
608	break;
609	case 0x3e: /* Read Long command. */
610	Log(("URB: %*s: SCSI: READ LONG RelAdr=%d Correct=%d LUN=%d LBA=%#RX16 ByteLen=%#RX16 Ctrl=%#RX8\n",
611	s_cchMaxMsg, pszMsg,
612	pb[1] & 1, !!(pb[1] & RT_BIT(1)), pb[1] >> 5,
613	RT_MAKE_U16(pb[3], pb[2]), RT_MAKE_U16(pb[6], pb[5]),
614	pb[11]));
615	break;
616	case 0x2a: /* Write(10) command. */
617	Log(("URB: %*s: SCSI: WRITE10 RelAdr=%d EBP=%d FUA=%d DPO=%d LUN=%d LBA=%#RX32 Len=%#RX16 Ctrl=%#RX8\n",
618	s_cchMaxMsg, pszMsg,
619	pb[1] & 1, !!(pb[1] & RT_BIT(2)), !!(pb[1] & RT_BIT(3)),
620	!!(pb[1] & RT_BIT(4)), pb[1] >> 5,
621	RT_MAKE_U32_FROM_U8(pb[5], pb[4], pb[3], pb[2]),
622	RT_MAKE_U16(pb[8], pb[7]), pb[9]));
623	break;
624	case 0xaa: /* Write(12) command. */
625	Log(("URB: %*s: SCSI: WRITE12 RelAdr=%d EBP=%d FUA=%d DPO=%d LUN=%d LBA=%#RX32 Len=%#RX32 Ctrl=%#RX8\n",
626	s_cchMaxMsg, pszMsg,
627	pb[1] & 1, !!(pb[1] & RT_BIT(3)), !!(pb[1] & RT_BIT(4)),
628	!!(pb[1] & RT_BIT(4)), pb[1] >> 5,
629	RT_MAKE_U32_FROM_U8(pb[5], pb[4], pb[3], pb[2]),
630	RT_MAKE_U32_FROM_U8(pb[9], pb[8], pb[7], pb[6]),
631	pb[11]));
632	break;
633	case 0x3f: /* Write Long command. */
634	Log(("URB: %*s: SCSI: WRITE LONG RelAdr=%d LUN=%d LBA=%#RX16 ByteLen=%#RX16 Ctrl=%#RX8\n",
635	s_cchMaxMsg, pszMsg,
636	pb[1] & 1, pb[1] >> 5,
637	RT_MAKE_U16(pb[3], pb[2]), RT_MAKE_U16(pb[6], pb[5]),
638	pb[11]));
639	break;
640	case 0x35: /* Synchronize Cache(10) command. */
641	Log(("URB: %*s: SCSI: SYNCHRONIZE_CACHE10\n",
642	s_cchMaxMsg, pszMsg));
643	break;
644	case 0xa0: /* Report LUNs command. */
645	Log(("URB: %*s: SCSI: REPORT_LUNS\n",
646	s_cchMaxMsg, pszMsg));
647	break;
648	default:
649	Log(("URB: %*s: SCSI: cmd=%#x\n",
650	s_cchMaxMsg, pszMsg, pb[0]));
651	break;
652	}
653	if (pDev)
654	pDev->Urb.u8ScsiCmd = pb[0];
655	}
656	else if ( fComplete
657	&& pUrb->enmType == VUSBXFERTYPE_BULK
658	&& pUrb->enmDir == VUSBDIRECTION_IN
659	&& pUrb->cbData >= 12
660	&& !memcmp(pUrb->abData, "USBS", 4))
661	{
662	const struct usbs
663	{
664	uint32_t Signature;
665	uint32_t Tag;
666	uint32_t DataResidue;
667	uint8_t Status;
668	uint8_t CDB[3];
669	} pUsbS = (struct usbs )pUrb->abData;
670	static const char * const s_apszStatuses[] = { "PASSED", "FAILED", "PHASE ERROR", "RESERVED" };
671	Log(("URB: %*s: SCSI: Tag=%#x DataResidue=%#RX32 Status=%#RX8 %s\n",
672	s_cchMaxMsg, pszMsg, pUsbS->Tag, pUsbS->DataResidue, pUsbS->Status,
673	s_apszStatuses[pUsbS->Status < RT_ELEMENTS(s_apszStatuses) ? pUsbS->Status : RT_ELEMENTS(s_apszStatuses) - 1]));
674	if (pDev)
675	pDev->Urb.u8ScsiCmd = 0xff;
676	}
677	else if ( fComplete
678	&& pUrb->enmType == VUSBXFERTYPE_BULK
679	&& pUrb->enmDir == VUSBDIRECTION_IN
680	&& pDev
681	&& pDev->Urb.u8ScsiCmd != 0xff)
682	{
683	const uint8_t *pb = pUrb->abData;
684	switch (pDev->Urb.u8ScsiCmd)
685	{
686	case 0x03: /* REQUEST_SENSE */
687	Log(("URB: %*s: SCSI: RESPONSE: REQUEST_SENSE (%s)\n",
688	s_cchMaxMsg, pszMsg, pb[0] & 7 ? "scsi compliant" : "not scsi compliant"));
689	Log(("URB: %*s: SCSI: ErrCd=%#RX8 (%s) Seg=%#RX8 Filemark=%d EOM=%d ILI=%d\n",
690	s_cchMaxMsg, pszMsg, pb[0] & 0x7f, GetScsiErrCd(pb[0] & 0x7f), pb[1],
691	pb[2] >> 7, !!(pb[2] & RT_BIT(6)), !!(pb[2] & RT_BIT(5))));
692	Log(("URB: %*s: SCSI: SenseKey=%#x ASC=%#RX8 ASCQ=%#RX8 : %s\n",
693	s_cchMaxMsg, pszMsg, pb[2] & 0xf, pb[12], pb[13],
694	GetScsiKCQ(pb[2] & 0xf, pb[12], pb[13])));
695	/** @todo more later */
696	break;
697
698	case 0x12: /* INQUIRY. */
699	{
700	unsigned cb = pb[4] + 5;
701	Log(("URB: %*s: SCSI: RESPONSE: INQUIRY\n"
702	"URB: %*s: SCSI: PeripheralQualifier=%d PeripheralType=%#RX8 RMB=%d DevTypeMod=%#RX8\n",
703	s_cchMaxMsg, pszMsg, s_cchMaxMsg, pszMsg,
704	pb[0] >> 5, pb[0] & 0x1f, pb[1] >> 7, pb[1] & 0x7f));
705	Log(("URB: %*s: SCSI: ISOVer=%d ECMAVer=%d ANSIVer=%d\n",
706	s_cchMaxMsg, pszMsg, pb[2] >> 6, (pb[2] >> 3) & 7, pb[2] & 7));
707	Log(("URB: %*s: SCSI: AENC=%d TrmlOP=%d RespDataFmt=%d (%s) AddLen=%d\n",
708	s_cchMaxMsg, pszMsg, pb[3] >> 7, (pb[3] >> 6) & 1,
709	pb[3] & 0xf, pb[3] & 0xf ? "legacy" : "scsi", pb[4]));
710	if (cb < 8)
711	break;
712	Log(("URB: %*s: SCSI: RelAdr=%d WBus32=%d WBus16=%d Sync=%d Linked=%d CmdQue=%d SftRe=%d\n",
713	s_cchMaxMsg, pszMsg, pb[7] >> 7, !!(pb[7] >> 6), !!(pb[7] >> 5), !!(pb[7] >> 4),
714	!!(pb[7] >> 3), !!(pb[7] >> 1), pb[7] & 1));
715	if (cb < 16)
716	break;
717	Log(("URB: %*s: SCSI: VendorId=%.8s\n", s_cchMaxMsg, pszMsg, &pb[8]));
718	if (cb < 32)
719	break;
720	Log(("URB: %*s: SCSI: ProductId=%.16s\n", s_cchMaxMsg, pszMsg, &pb[16]));
721	if (cb < 36)
722	break;
723	Log(("URB: %*s: SCSI: ProdRevLvl=%.4s\n", s_cchMaxMsg, pszMsg, &pb[32]));
724	if (cb > 36)
725	Log(("URB: %s: SCSI: VendorSpecific=%.s\n",
726	s_cchMaxMsg, pszMsg, RT_MIN(cb - 36, 20), &pb[36]));
727	if (cb > 96)
728	Log(("URB: %s: SCSI: VendorParam=%.Rhxs\n",
729	s_cchMaxMsg, pszMsg, cb - 96, &pb[96]));
730	break;
731	}
732
733	case 0x25: /* Read Capacity(6) command. */
734	Log(("URB: %*s: SCSI: RESPONSE: READ_CAPACITY\n"
735	"URB: %*s: SCSI: LBA=%#RX32 BlockLen=%#RX32\n",
736	s_cchMaxMsg, pszMsg, s_cchMaxMsg, pszMsg,
737	RT_MAKE_U32_FROM_U8(pb[3], pb[2], pb[1], pb[0]),
738	RT_MAKE_U32_FROM_U8(pb[7], pb[6], pb[5], pb[4])));
739	break;
740	}
741
742	pDev->Urb.u8ScsiCmd = 0xff;
743	}
744
745	/*
746	* The Quickcam control pipe.
747	*/
748	if ( pSetup
749	&& ((pSetup->bmRequestType >> 5) & 0x3) >= 2 /* vendor */
750	&& (fComplete \|\| !(pSetup->bmRequestType >> 7))
751	&& pDev
752	&& pDev->pDescCache
753	&& pDev->pDescCache->pDevice
754	&& pDev->pDescCache->pDevice->idVendor == 0x046d
755	&& ( pDev->pDescCache->pDevice->idProduct == 0x8f6
756	\|\| pDev->pDescCache->pDevice->idProduct == 0x8f5
757	\|\| pDev->pDescCache->pDevice->idProduct == 0x8f0)
758	)
759	{
760	pbData = (const uint8_t *)(pSetup + 1);
761	cbData = pUrb->cbData - sizeof(*pSetup);
762
763	if ( pSetup->bRequest == 0x04
764	&& pSetup->wIndex == 0
765	&& (cbData == 1 \|\| cbData == 2))
766	{
767	/* the value */
768	unsigned uVal = pbData[0];
769	if (cbData > 1)
770	uVal \|= (unsigned)pbData[1] << 8;
771
772	const char *pszReg = NULL;
773	switch (pSetup->wValue)
774	{
775	case 0: pszReg = "i2c init"; break;
776	case 0x0423: pszReg = "STV_REG23"; break;
777	case 0x0509: pszReg = "RED something"; break;
778	case 0x050a: pszReg = "GREEN something"; break;
779	case 0x050b: pszReg = "BLUE something"; break;
780	case 0x143f: pszReg = "COMMIT? INIT DONE?"; break;
781	case 0x1440: pszReg = "STV_ISO_ENABLE"; break;
782	case 0x1442: pszReg = uVal & (RT_BIT(7)\|RT_BIT(5)) ? "BUTTON PRESSED" : "BUTTON" ; break;
783	case 0x1443: pszReg = "STV_SCAN_RATE"; break;
784	case 0x1445: pszReg = "LED?"; break;
785	case 0x1500: pszReg = "STV_REG00"; break;
786	case 0x1501: pszReg = "STV_REG01"; break;
787	case 0x1502: pszReg = "STV_REG02"; break;
788	case 0x1503: pszReg = "STV_REG03"; break;
789	case 0x1504: pszReg = "STV_REG04"; break;
790	case 0x15c1: pszReg = "STV_ISO_SIZE"; break;
791	case 0x15c3: pszReg = "STV_Y_CTRL"; break;
792	case 0x1680: pszReg = "STV_X_CTRL"; break;
793	case 0xe00a: pszReg = "ProductId"; break;
794	default: pszReg = "[no clue]"; break;
795	}
796	if (pszReg)
797	Log(("URB: %*s: QUICKCAM: %s %#x (%d) %s '%s' (%#x)\n",
798	s_cchMaxMsg, pszMsg,
799	(pSetup->bmRequestType >> 7) ? "read" : "write", uVal, uVal, (pSetup->bmRequestType >> 7) ? "from" : "to",
800	pszReg, pSetup->wValue));
801	}
802	else if (cbData)
803	Log(("URB: %s: QUICKCAM: Unknown request: bRequest=%#x bmRequestType=%#x wValue=%#x wIndex=%#x: %.Rhxs\n", s_cchMaxMsg, pszMsg,
804	pSetup->bRequest, pSetup->bmRequestType, pSetup->wValue, pSetup->wIndex, cbData, pbData));
805	else
806	Log(("URB: %*s: QUICKCAM: Unknown request: bRequest=%#x bmRequestType=%#x wValue=%#x wIndex=%#x: (no data)\n", s_cchMaxMsg, pszMsg,
807	pSetup->bRequest, pSetup->bmRequestType, pSetup->wValue, pSetup->wIndex));
808	}
809
810	#if 1
811	if ( cbData /** @todo Fix RTStrFormatV to communicate .* so formatter doesn't apply defaults when cbData=0. */
812	&& (fComplete
813	? pUrb->enmDir != VUSBDIRECTION_OUT
814	: pUrb->enmDir == VUSBDIRECTION_OUT))
815	Log3(("%16.*Rhxd\n", cbData, pbData));
816	#endif
817	if (pUrb->enmType == VUSBXFERTYPE_MSG && pUrb->pVUsb && pUrb->pVUsb->pCtrlUrb)
818	vusbUrbTrace(pUrb->pVUsb->pCtrlUrb, "NESTED MSG", fComplete);
819	}
820	#endif /* LOG_ENABLED */
821

Note: See TracBrowser for help on using the repository browser.

source: vbox/trunk/src/VBox/Devices/USB/VUSBUrbTrace.cpp@ 91881

Download in other formats: