1 /*++
2
3 Copyright (c) Microsoft Corporation
4
5 Module Name:
6
7 Tracing.cpp
8
9 Abstract:
10
11 This module implements tracing for the driver frameworks
12
13 Author:
14
15
16
17
18 Revision History:
19
20
21
22
23 --*/
24
25 #include "FxSupportPch.hpp"
26 #include "fxldrum.h"
27
28 extern "C" {
29 #if defined(EVENT_TRACING)
30 #include "TracingUM.tmh"
31 #endif
32 }
33
34 #include <strsafe.h>
35 #include <initguid.h>
36 #include "fxIFR.h" // shared struct between IFR and debug ext.
37 #include "fxIFRKm.h" // kernel mode only IFR definitions
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254 _Must_inspect_result_
255 NTSTATUS
FxTraceInitialize(VOID)256 FxTraceInitialize(
257 VOID
258 )
259
260 /*++
261
262 Routine Description:
263
264 This routine initializes the frameworks tracing.
265
266 It must be called early on in the frameworks DriverEntry
267 initialization.
268
269 Arguments:
270
271 None
272
273 Returns:
274
275 NTSTATUS code
276
277 --*/
278 {
279 //
280 // Initialize the tracing package.
281 //
282 WPP_INIT_TRACING(NULL, NULL);
283
284 return STATUS_SUCCESS;
285 }
286
287 VOID
TraceUninitialize(VOID)288 TraceUninitialize(
289 VOID
290 )
291 /*++
292
293 Routine Description:
294 This routine uninitializes the frameworks tracing. It must be called just
295 before DriverUnload
296
297 Arguments:
298 None
299
300 Returns:
301 None
302
303 --*/
304 {
305 WPP_CLEANUP(NULL);
306 }
307
308 _Must_inspect_result_
309 NTSTATUS
FxWmiQueryTraceInformation(__in TRACE_INFORMATION_CLASS,__out_bcount (TraceInformationLength)PVOID,__in ULONG,__out_opt PULONG,__in_opt PVOID)310 FxWmiQueryTraceInformation(
311 __in TRACE_INFORMATION_CLASS /* TraceInformationClass */,
312 __out_bcount(TraceInformationLength) PVOID /* TraceInformation */,
313 __in ULONG /* TraceInformationLength */,
314 __out_opt PULONG /* RequiredLength */,
315 __in_opt PVOID /* Buffer */
316 )
317 {
318 return STATUS_UNSUCCESSFUL;
319 }
320
321 _Must_inspect_result_
322 NTSTATUS
FxWmiTraceMessage(__in TRACEHANDLE LoggerHandle,__in ULONG MessageFlags,__in LPGUID MessageGuid,__in USHORT MessageNumber,...)323 FxWmiTraceMessage(
324 __in TRACEHANDLE LoggerHandle,
325 __in ULONG MessageFlags,
326 __in LPGUID MessageGuid,
327 __in USHORT MessageNumber,
328 ...
329 )
330 {
331 NTSTATUS status = STATUS_SUCCESS;
332
333 va_list va;
334 va_start(va, MessageNumber);
335 //
336 // UMDF is supported only on XP and newer OS so no need to support w2k
337 // tracing (which requires using a different tracing api, see kmdf impl)
338 //
339 #pragma prefast(suppress:__WARNING_BUFFER_OVERFLOW, "Recommneded by EndClean");
340 status = TraceMessageVa(LoggerHandle,
341 MessageFlags,
342 MessageGuid,
343 MessageNumber,
344 va);
345
346 va_end(va);
347
348 return status;
349 }
350
351
352 //-----------------------------------------------------------------------------
353 // Subcomponents for the In-Flight Recorder follow.
354 //-----------------------------------------------------------------------------
355
356 ULONG
FxIFRGetSize(__in PFX_DRIVER_GLOBALS FxDriverGlobals,__in PCUNICODE_STRING RegistryPath)357 FxIFRGetSize(
358 __in PFX_DRIVER_GLOBALS FxDriverGlobals,
359 __in PCUNICODE_STRING RegistryPath
360 )
361 /*++
362
363 Routine Description:
364 Checks to see if the service has overriden the default number of pages that
365 are in the IFR.
366
367 Arguments:
368 RegistryPath - path to the service
369
370 Return Value:
371 The size of the IFR to create in bytes (not pages!)
372
373 --*/
374 {
375 FxAutoRegKey service, parameters;
376 NTSTATUS status;
377 ULONG numPages;
378
379 //
380 // This is the value used in case of any error while retrieving 'LogPages'
381 // from the registry.
382 //
383 numPages = FxIFRMinLogPages;
384
385 //
386 // External representation of the IFR is the "log", so use tha term when
387 // overriding the size via the registry.
388 //
389 DECLARE_CONST_UNICODE_STRING(parametersPath, L"Parameters\\Wdf");
390 DECLARE_CONST_UNICODE_STRING(valueName, L"LogPages");
391
392 //
393 // UMDF may not provide this registry path
394 //
395 if (NULL == RegistryPath) {
396 goto defaultValues;
397 }
398
399 status = FxRegKey::_OpenKey(NULL,
400 (PCUNICODE_STRING)RegistryPath,
401 &service.m_Key,
402 KEY_READ);
403 if (!NT_SUCCESS(status)) {
404 goto defaultValues;
405 }
406
407 status = FxRegKey::_OpenKey(service.m_Key,
408 (PCUNICODE_STRING)¶metersPath,
409 ¶meters.m_Key,
410 KEY_READ);
411 if (!NT_SUCCESS(status)) {
412 goto defaultValues;
413 }
414
415 status = FxRegKey::_QueryULong(parameters.m_Key, &valueName, &numPages);
416 if (!NT_SUCCESS(status)) {
417 goto defaultValues;
418 }
419
420 if (numPages == 0) {
421 numPages = FxIFRMinLogPages;
422 }
423
424 defaultValues:
425 //
426 // This behavior is different from KMDF. KMDF would allocate Average page count (5)
427 // if Verifier is on otherwise 1 page if the request is large.
428 // Since for UMDF the memory is coming from WudfRd, which does not know about verifier
429 // we will give it max pages here.
430 //
431 if (numPages > FxIFRMaxLogPages) {
432 numPages = FxIFRMaxLogPages;
433 }
434
435 return numPages * PAGE_SIZE;
436 }
437
438 VOID
FxIFRStart(__in PFX_DRIVER_GLOBALS FxDriverGlobals,__in PCUNICODE_STRING RegistryPath,__in MdDriverObject DriverObject)439 FxIFRStart(
440 __in PFX_DRIVER_GLOBALS FxDriverGlobals,
441 __in PCUNICODE_STRING RegistryPath,
442 __in MdDriverObject DriverObject
443 )
444 /*++
445
446 Routine Description:
447
448 This routine initialize the In-Flight Recorder (IFR).
449
450 The default log size is set by WDF_IFR_LOG_SIZE and currently
451 is 4096 (one x86 page).
452 This routine should be called very early in driver initialization
453 to allow the capture of all significant events.
454
455 Arguments:
456
457 Returns:
458
459 --*/
460 {
461 PWDF_IFR_HEADER pHeader;
462 ULONG pageCount;
463 ULONG sizeCb;
464 HRESULT hr;
465 IWudfDeviceStack2 *pDeviceStack2;
466 PDRIVER_OBJECT_UM umDriverObject;
467 PWCHAR serviceName;
468 size_t bufferLengthCch;
469 ULONG allocatedBufferLengthCb;
470 LONG i;
471
472 //
473 // Return early if IFR is disabled.
474 //
475 if (FxLibraryGlobals.IfrDisabled) {
476 ASSERT(FxDriverGlobals->WdfLogHeader == NULL);
477 return;
478 }
479
480 WDFCASSERT(FxIFRRecordSignature == WDF_IFR_RECORD_SIGNATURE);
481
482 if (FxDriverGlobals == NULL || FxDriverGlobals->WdfLogHeader != NULL) {
483 return;
484 }
485
486 //
487 // It is safe to use StringCchLength here as WudfHost makes sure that this
488 // RegistryPath is null terminated
489 //
490 hr = StringCchLength(RegistryPath->Buffer,
491 RegistryPath->MaximumLength/sizeof(WCHAR),
492 &bufferLengthCch);
493
494 if (FAILED(hr)) {
495 return;
496 }
497
498 //
499 // Lets find the last '\' that will mark the begining of the service name
500 //
501 for (i = (ULONG)bufferLengthCch - 1;
502 i >= 0 && RegistryPath->Buffer[i] != '\\';
503 i--);
504
505 //
506 // We did not find the service name
507 //
508 if (i < 0) {
509 return;
510 }
511
512 serviceName = &RegistryPath->Buffer[i+1];
513
514 sizeCb = FxIFRGetSize(FxDriverGlobals, RegistryPath);
515 pageCount = sizeCb / PAGE_SIZE;
516
517 //
518 // Get the IWudfDeviceStack interface
519 //
520 umDriverObject = (PDRIVER_OBJECT_UM)DriverObject;
521
522 pDeviceStack2 = (IWudfDeviceStack2 *)umDriverObject->WudfDevStack;
523
524 if(pDeviceStack2 == NULL) {
525 return;
526 }
527
528 allocatedBufferLengthCb = 0;
529 hr = pDeviceStack2->AllocateIfrMemory(serviceName,
530 pageCount,
531 FALSE,
532 TRUE,
533 (PVOID *)&pHeader,
534 &allocatedBufferLengthCb);
535
536 if (pHeader == NULL || allocatedBufferLengthCb <= sizeof(WDF_IFR_HEADER)) {
537 return;
538 }
539
540 //
541 // Initialize the header.
542 // Base will be where the IFR records are placed.
543 // WPP_ThisDir_CTLGUID_FrameworksTraceGuid
544 //
545 RtlCopyMemory(&pHeader->Guid, (PVOID) &WdfTraceGuid, sizeof(GUID));
546
547 pHeader->Base = (PUCHAR) &pHeader[1];
548 pHeader->Size = allocatedBufferLengthCb - sizeof(WDF_IFR_HEADER);
549
550 pHeader->Offset.u.s.Current = 0;
551 pHeader->Offset.u.s.Previous = 0;
552 pHeader->SequenceNumberPointer = &(DriverObject->IfrSequenceNumber);
553
554 StringCchCopyA(pHeader->DriverName, WDF_IFR_HEADER_NAME_LEN, FxDriverGlobals->Public.DriverName);
555
556 FxDriverGlobals->WdfLogHeader = pHeader;
557
558 DoTraceLevelMessage(FxDriverGlobals, TRACE_LEVEL_VERBOSE, TRACINGDRIVER,
559 "FxIFR logging started" );
560
561 if (sizeCb > FxIFRMinLogSize) {
562 DoTraceLevelMessage(
563 FxDriverGlobals, TRACE_LEVEL_INFORMATION, TRACINGDRIVER,
564 "FxIFR has been started with a size override: size 0x%x bytes, "
565 "# Pages %d. An extended IFR size may not be written to a minidump!",
566 sizeCb, sizeCb/PAGE_SIZE);
567 }
568
569 if (sizeCb != allocatedBufferLengthCb) {
570 ASSERTMSG("FxIFR requested buffer size could not be allocated",FALSE);
571 DoTraceLevelMessage(
572 FxDriverGlobals, TRACE_LEVEL_WARNING, TRACINGDRIVER,
573 "FxIFR requested an allocation of size 0x%x bytes, "
574 "Allocated memory was of size 0x%x bytes",
575 sizeCb, allocatedBufferLengthCb);
576 }
577 }
578
579 VOID
FxIFRStop(__in PFX_DRIVER_GLOBALS FxDriverGlobals)580 FxIFRStop(
581 __in PFX_DRIVER_GLOBALS FxDriverGlobals
582 )
583 /*++
584
585 Routine Description:
586
587 This routine stops the In-Flight Recorder (IFR).
588
589 For UMDF FxIFRStop is no longer required as WudfRd manages the buffer's lifetime
590 The buffer is kept alive till WudfRd unloads to aid in debugging in cases of
591 WudfHost crash or in dumps with WudfHost paged out or not captured
592
593 Arguments:
594
595 Returns:
596
597 --*/
598 {
599 UNREFERENCED_PARAMETER(FxDriverGlobals);
600
601 //
602 // Uncomment the code below if you add any logic to this function.
603 //
604 // if (FxLibraryGlobals.IfrDisabled) {
605 // ASSERT(FxDriverGlobals->WdfLogHeader == NULL);
606 // return;
607 // }
608 //
609 }
610
611 _Must_inspect_result_
612 NTSTATUS
FxIFR(__in PFX_DRIVER_GLOBALS FxDriverGlobals,__in UCHAR MessageLevel,__in ULONG MessageFlags,__in LPGUID MessageGuid,__in USHORT MessageNumber,...)613 FxIFR(
614 __in PFX_DRIVER_GLOBALS FxDriverGlobals,
615 __in UCHAR MessageLevel,
616 __in ULONG MessageFlags,
617 __in LPGUID MessageGuid,
618 __in USHORT MessageNumber,
619 ...
620 )
621 /*++
622
623 Routine Description:
624
625 This routine is the main In-Flight Recorder (IFR) routine.
626
627 It captures a WPP message to the IFR log.
628 The IFR is always running, e.g. not WPP logger is necessary
629 to start logging.
630
631 Arguments:
632
633 MessageLevel - The WPP message level for this event
634 MessageFlags - The WPP message flags for this event (see trace GUID)
635 MessageGuid - The tracewpp generated guid for module emitting this event.
636 MessageNumber - The tracewpp generated message number within
637 the emitting module.
638 ... - Variable arguments associates with the emitted message.
639
640 Returns:
641
642 NTSTATUS
643
644 --*/
645 {
646 size_t size;
647 PWDF_IFR_RECORD record;
648
649 UNREFERENCED_PARAMETER( MessageLevel );
650
651 //
652 // Return early if IFR is disabled.
653 //
654 if (FxLibraryGlobals.IfrDisabled) {
655 ASSERT(FxDriverGlobals->WdfLogHeader == NULL);
656 return STATUS_SUCCESS;
657 }
658
659 if ( FxDriverGlobals->WdfLogHeader == NULL) {
660 return STATUS_UNSUCCESSFUL;
661 }
662
663
664
665
666
667
668
669
670
671
672
673
674
675
676
677
678
679
680
681
682
683
684
685
686
687 UNREFERENCED_PARAMETER( MessageFlags );
688
689
690 //
691 // Determine the number bytes to follow header
692 //
693 size = 0; // For Count of Bytes
694
695 //
696 // Determine how much log space is needed for this
697 // trace record's data.
698 //
699 {
700 va_list ap;
701 size_t argLen;
702
703 va_start(ap, MessageNumber);
704 #pragma prefast(suppress: __WARNING_BUFFER_OVERFLOW, "Recommneded by EndClean");
705 while ((va_arg(ap, PVOID)) != NULL) {
706
707 argLen = va_arg(ap, size_t);
708
709 if (argLen > 0) {
710
711 if (argLen > FxIFRMaxMessageSize) {
712 goto drop_message;
713 }
714 size += (USHORT) argLen;
715 }
716 }
717
718 va_end(ap);
719
720 //
721 // NOTE: The final size must be 32-bit (ULONG) aligned.
722 // This is necessary for IA64 to prevent Alignment Faults.
723 //
724 size += (size % sizeof(ULONG)) ? sizeof(ULONG) - (size % sizeof(ULONG)) : 0;
725
726 if (size > FxIFRMaxMessageSize) {
727 goto drop_message;
728 }
729 }
730
731 size += sizeof(WDF_IFR_RECORD);
732
733 //
734 // Allocate log space of the calculated size
735 //
736 {
737 PWDF_IFR_HEADER header;
738 WDF_IFR_OFFSET offsetRet;
739 WDF_IFR_OFFSET offsetCur;
740 WDF_IFR_OFFSET offsetNew;
741 USHORT usSize = (USHORT) size; // for a prefast artifact.
742
743 header = (PWDF_IFR_HEADER) FxDriverGlobals->WdfLogHeader;
744 ASSERT(header->Size < FxIFRMaxLogSize); // size doesn't include header.
745 ASSERT(header->Size >= header->Offset.u.s.Current);
746 ASSERT(header->Size >= header->Offset.u.s.Previous);
747
748 offsetRet.u.AsLONG = header->Offset.u.AsLONG;
749 offsetNew.u.AsLONG = offsetRet.u.s.Current;
750
751 do {
752 offsetCur.u.AsLONG = offsetRet.u.AsLONG;
753
754 if (&header->Base[header->Size] < &header->Base[offsetCur.u.s.Current+size]) {
755
756 offsetNew.u.s.Current = 0;
757 offsetNew.u.s.Previous = offsetRet.u.s.Previous;
758
759 offsetRet.u.AsLONG =
760 InterlockedCompareExchange( &header->Offset.u.AsLONG,
761 offsetNew.u.AsLONG,
762 offsetCur.u.AsLONG );
763
764 if (offsetCur.u.AsLONG != offsetRet.u.AsLONG) {
765 continue;
766 } else {
767 offsetNew.u.s.Current = offsetCur.u.s.Current + usSize;
768 offsetNew.u.s.Previous = offsetRet.u.s.Current;
769 }
770 } else {
771
772 offsetNew.u.s.Current = offsetCur.u.s.Current + usSize;
773 offsetNew.u.s.Previous = offsetCur.u.s.Current;
774 }
775
776 offsetRet.u.AsLONG =
777 InterlockedCompareExchange( &header->Offset.u.AsLONG,
778 offsetNew.u.AsLONG,
779 offsetCur.u.AsLONG );
780
781 } while (offsetCur.u.AsLONG != offsetRet.u.AsLONG);
782
783 record = (PWDF_IFR_RECORD) &header->Base[offsetRet.u.s.Current];
784
785 // RtlZeroMemory( record, sizeof(WDF_IFR_RECORD) );
786
787 //
788 // Build record (fill all fields!)
789 //
790 record->Signature = FxIFRRecordSignature;
791 record->Length = (USHORT) size;
792 record->PrevOffset = (USHORT) offsetRet.u.s.Previous;
793 record->MessageNumber = MessageNumber;
794 record->Sequence = InterlockedIncrement(header->SequenceNumberPointer);
795 record->MessageGuid = *MessageGuid;
796 }
797
798 //
799 // Move variable part of data into log.
800 //
801 {
802 va_list ap;
803 size_t argLen;
804 PVOID source;
805 PUCHAR argsData;
806
807 argsData = (UCHAR*) &record[1];
808
809 va_start(ap, MessageNumber);
810 #pragma prefast(suppress: __WARNING_BUFFER_OVERFLOW, "Recommneded by EndClean");
811 while ((source = va_arg(ap, PVOID)) != NULL) {
812
813 argLen = va_arg(ap, size_t);
814
815 if (argLen > 0) {
816
817 RtlCopyMemory( argsData, source, argLen );
818 argsData += argLen;
819 }
820 }
821
822 va_end(ap);
823 }
824
825 return STATUS_SUCCESS;
826
827 {
828 //
829 // Increment sequence number to indicate dropped message
830 //
831 drop_message:
832 PWDF_IFR_HEADER header;
833 header = (PWDF_IFR_HEADER) FxDriverGlobals->WdfLogHeader;
834 InterlockedIncrement(header->SequenceNumberPointer);
835 return STATUS_UNSUCCESSFUL;
836 }
837 }
838
839