Once the created application started, it is always better to know what is happening inside your program and does it execute correctly or something went wrong. For such purposes, systems have lots of helper things, but most programmers know not many of them and use usually only one way. This article shows you the simple ways to provide information for tracing and receive how to do it in C++ and C# applications.
Table of Contents
Basic tracing ways is good to check functionality of your application without involving something specific or digging deeper into any special technology for that.
In this topic, we review the implementation of the most popular and simple ways of providing tracing information. We also discuss moments how to extend those tracing ways and receive the tracing notifications of those methods. We find out how the debuggers and the DbgView tool works.
Then developing applications we should think and design a way to provide some test information of the progress of execution. It is not good if the application just closed without any notification or information about what went wrong. A simple way to provide tracing information if you are developing a console application is just output information into stderr. This is the basics of what we know from the beginning of study programming.
#include <stdio.h>
#include <conio.h>
int main(int argc, char* argv[])
{
fprintf(stderr, "Something went wrong\n");
_getch();
return 0;
}
For those who prefer output with the std stream, can use std::cerr.
#include <iostream>
#include <conio.h>
int main(int argc, char* argv[])
{
using namespace std;
cerr << "Something went wrong" << endl;
_getch();
return 0;
}
.NET has a Console.Error object for those purposes. It is the special IO.TextWriter class which represents stderr.
static void Main(string[] args)
{
Console.Error.WriteLine("Something went wrong");
Console.ReadKey();
}
The result execution is simply displaying text in the console window.
Ok, right now, we already understand what may have gone wrong depending on the message we output. But, what if we do not have a console application? In that case, we can also use the console output and just create a console window in case we are required to display some information. To create console windows, the AllocConsole API is used. After allocating the console, we should reopen the stderr stream with freopen API.
#include <stdio.h>
#include <windows.h>
int WINAPI WinMain(HINSTANCE hInstance,HINSTANCE hPrevInstance,
LPSTR lpCmdLine,int nCmdShow)
{
FILE *out_stream = stderr;
if (AllocConsole()) {
freopen_s(&out_stream,"CONOUT$", "w", stderr);
}
fprintf(out_stream, "Something went wrong\n");
MessageBoxA(NULL,"Application Quit","",MB_OK);
return 0;
}
The std::cerr should be cleared to reset the output buffer. This is done by calling the cerr.clear() method.
You can say that “such technique with allocating console for tracing is not used anywhere” and you will be wrong, as well-known VLC player doing that:
If you follow the menu in the picture, the console window pops-up and you can see the tracing information which is provided by the application. For example, my version of VLC does not handle video codec and it notifies that in pop-up dialog, but I can find detailed information in the console window:
In our application, we can design that the console window will be opened from the menu or as a startup argument, or just always displaying on building debug configuration.
On a .NET Windows application calling AllocConsole API also opens the console window, but if the application is running under Visual Studio, the console window is not associated with output, and writing text into the console causes display messages in the output window.
The regular Windows applications are executed not under Visual Studio. Once the console allocated, those methods provide correct output into the console window. Calling reset output stream, like we do in C++ implementation, is not required in .NET applications.
[DllImport("kernel32.dll", CallingConvention = CallingConvention.StdCall,
SetLastError = true)]
[return: MarshalAs(UnmanagedType.Bool)]
static extern bool AllocConsole();
static void Main(string[] args)
{
AllocConsole();
Console.WriteLine("Something went wrong");
MessageBox.Show("Application Quit");
}
Result of programs execution not under Visual Studio:
Console input and output streams can be redirected which give us a way to save regular output into a file. Allocating the console window is not necessary for this. In that case, we will be calling the same API which we already mentioned: freopen. The output buffer of std::cerr should also be cleared by calling the cerr.clear() method. We can use the information which is saved in a file later to determine what was wrong.
#include <stdio.h>
#include <windows.h>
#include <iostream>
int WINAPI WinMain(HINSTANCE hInstance,HINSTANCE hPrevInstance,
LPSTR lpCmdLine,int nCmdShow)
{
using namespace std;
FILE *temp;
freopen_s(&temp,"d:\\temp.log", "w", stderr);
cerr.clear();
fprintf(stderr, "Something went wrong\n");
cerr << "Another message" << endl;
MessageBoxA(NULL,"Application Quit","",MB_OK);
return 0;
}
As a result, we do not see the console window at all, but the new file d:\temp.log created after the application executes.
.NET also allows you to redirect console output into a file. The next code displays creating a StreamWriter object and passing it as an output of the console error stream. As the result of execution, we also have the d:\temp.log file.
using System;
using System.IO;
using System.Text;
using System.Windows.Forms;
class Program
{
static void Main(string[] args)
{
var sw = new StreamWriter(@"d:\temp.log", true, Encoding.ASCII);
Console.SetError(sw);
Console.Error.WriteLine("Something went wrong");
MessageBox.Show("Application Quit");
sw.Dispose();
}
}
It is also possible to get the file handle of the console output stream and use it with files API. And if there is no console of the application - then such handle is empty.
#include <stdio.h>
#include <windows.h>
void TracePrint(const char * format, ...)
{
HANDLE hFile = GetStdHandle(STD_ERROR_HANDLE);
if (hFile && hFile != INVALID_HANDLE_VALUE) {
va_list args;
va_start(args, format);
int _length = _vscprintf(format, args) + 1;
char * _string = (char *)malloc(_length);
if (_string) {
memset(_string, 0, _length);
_vsprintf_p(_string, _length, format, args);
__try {
DWORD dw = 0;
WriteFile(hFile,_string,_length,&dw,NULL);
} __finally {
free(_string);
}
}
va_end(args);
}
}
int WINAPI wWinMain(HINSTANCE hInstance, HINSTANCE hPrevInstance,
LPWSTR lpCmdLine, int nCmdShow)
{
AllocConsole();
TracePrint("Something went wrong\n");
MessageBoxA(NULL,"Application Quit","",MB_OK);
}
The example above allocates the console window and writes formatted text messages into it. This works correctly once we have the console. But if we comment the line with the call AllocConsole API, then under debugger, we can see that the output handle is invalid. So, in the application, it is possible to design output depending on settings, build or command line arguments.
In .NET, it is also possible to fully redirect console output. To handle console output redirection necessary to create your own class and inherit it from TextWriter. In that class, it is required to override two Write methods and Encoding property. Sample of such class implementation is below:
class MyConsoleWriter : TextWriter
{
public override Encoding Encoding { get { return Encoding.Default; } }
public MyConsoleWriter() { }
public override void Write(string value)
{
IntPtr file = fopen("d:\\mylog.txt", "ab+");
var bytes = Encoding.Default.GetBytes(value);
fwrite(bytes, 1, bytes.Length, file);
fclose(file);
}
public override void WriteLine(string value)
{
Write((string.IsNullOrEmpty(value) ? "" : value) + "\n");
}
}
And after it needed to set an instance of that class as output of the console by calling Console.SetOut method.
static void Main(string[] args)
{
Console.SetOut(new MyConsoleWriter());
Console.WriteLine("Simple Console Output Message");
MessageBox.Show("Application Quit");
}
In the result of the execution program above will be the file mylog.txt on drive d:\. You can see the content of the file in the following screenshot:
Another interesting way of getting information about the application workflow is to attach the parent console from the child process, so the application provides information to its parent. So, the regular application is the Windows application and has no console window, but it uses functions for writing console output in a common way. And under the tracing mode, the application starts itself with an allocated console window, so the child process is attached to it. Let’s modify the previous code example for such implementation:
int WINAPI wWinMain(HINSTANCE hInstance,HINSTANCE hPrevInstance,
LPWSTR lpCmdLine,int nCmdShow)
{
INT nArgs;
LPWSTR * pszArgv = CommandLineToArgvW(lpCmdLine, &nArgs);
if (pszArgv && nArgs >= 1 && _wcsicmp(pszArgv[0], L"child") == 0) {
AttachConsole(ATTACH_PARENT_PROCESS);
int idx = 0;
while (idx++ < 100){
TracePrint("Child Message #%d\n",idx);
Sleep(100);
}
} else {
WCHAR szPath[1024] = {0};
GetModuleFileNameW(NULL,szPath + 1,_countof(szPath) - 1);
szPath[0] = '\"';
wcscat_s(szPath,L"\" child");
AllocConsole();
PROCESS_INFORMATION pi = {0};
STARTUPINFO si = {0};
si.cb = sizeof(STARTUPINFO);
if (CreateProcess(NULL, szPath, NULL, NULL, TRUE, 0, NULL, NULL, &si, &pi)) {
WaitForSingleObject(pi.hThread, INFINITE);
CloseHandle(pi.hProcess);
CloseHandle(pi.hThread);
MessageBoxA(NULL, "Application Quit", "", MB_OK);
}
}
if (pszArgv) LocalFree(pszArgv);
return 0;
}
So, we have a Windows application where we allocate a console and start a child process, which is also a Windows application. In that process, we attach to the parent console and provide some messages in a loop. Once the child process is finished, the parent shows the message box.
That is also possible to create in .NET. We just need to have a wrapper for AttachConsole and AllocConsole APIs.
using System;
using System.Runtime.InteropServices;
using System.Threading;
using System.Diagnostics;
using System.Windows.Forms;
class Program
{
[DllImport("kernel32.dll", CallingConvention = CallingConvention.StdCall,
SetLastError = true)]
[return: MarshalAs(UnmanagedType.Bool)]
static extern bool AllocConsole();
[DllImport("kernel32.dll", CallingConvention = CallingConvention.StdCall,
SetLastError = true)]
[return: MarshalAs(UnmanagedType.Bool)]
static extern bool AttachConsole([In,MarshalAs(UnmanagedType.U4)] int dwProcessId);
static void Main(string[] args)
{
if (args.Length >= 1 && args[0].ToLower() == "child")
{
AttachConsole(-1);
int idx = 0;
while (idx++ < 100)
{
Console.WriteLine(string.Format("Child Message #{0}", idx));
Thread.Sleep(100);
}
}
else
{
AllocConsole();
var process = Process.Start(Application.ExecutablePath, "child");
if (process != null)
{
process.WaitForExit();
process.Dispose();
MessageBox.Show("Application Quit");
}
}
}
}
The result of the execution code above is the same as in C++ version.
If you don’t want to have a console window at all, then it is possible to create a pipe and replace the standard error output handle of the child process, so the parent process also receives the information. Let's modify the previous code sample to see the implementation:
int WINAPI wWinMain(HINSTANCE hInstance,HINSTANCE hPrevInstance,
LPWSTR lpCmdLine,int nCmdShow)
{
INT nArgs;
LPWSTR * pszArgv = CommandLineToArgvW(lpCmdLine, &nArgs);
if (pszArgv && nArgs >= 1 && _wcsicmp(pszArgv[0], L"child") == 0) {
int idx = 0;
while (idx++ < 100) {
TracePrint("Child Message #%d\n",idx);
Sleep(100);
}
} else {
WCHAR szPath[1024] = {0};
GetModuleFileNameW(NULL,szPath + 1,_countof(szPath) - 1);
szPath[0] = '\"';
wcscat_s(szPath,L"\" child");
AllocConsole();
SECURITY_ATTRIBUTES sa = {0};
sa.nLength = sizeof(SECURITY_ATTRIBUTES);
sa.bInheritHandle = TRUE;
sa.lpSecurityDescriptor = NULL;
HANDLE hChildInReadPipe = NULL;
HANDLE hChildInWritePipe = NULL;
HANDLE hChildOutReadPipe = NULL;
HANDLE hChildOutWritePipe = NULL;
if (CreatePipe(&hChildOutReadPipe, &hChildOutWritePipe, &sa, 0)) {
SetHandleInformation(hChildOutReadPipe, HANDLE_FLAG_INHERIT, 0);
if (CreatePipe(&hChildInReadPipe, &hChildInWritePipe, &sa, 0)) {
SetHandleInformation(hChildInWritePipe, HANDLE_FLAG_INHERIT, 0);
PROCESS_INFORMATION pi = {0};
STARTUPINFO si = {0};
si.cb = sizeof(STARTUPINFO);
si.hStdError = hChildOutWritePipe;
si.hStdOutput = hChildOutWritePipe;
si.hStdInput = hChildInReadPipe;
si.dwFlags |= STARTF_USESTDHANDLES;
if (CreateProcess(NULL, szPath, NULL, NULL, TRUE, 0,
NULL, NULL, &si, &pi)) {
HANDLE hCurrentHandle = GetStdHandle(STD_ERROR_HANDLE);
while (true) {
DWORD dwRead = 0;
BYTE buf[1024] = { 0 };
if (PeekNamedPipe(hChildOutReadPipe,buf,sizeof(buf),
&dwRead,NULL,NULL) && dwRead) {
if (!ReadFile(hChildOutReadPipe, buf,
sizeof(buf), &dwRead, NULL) || dwRead == 0) {
break;
}
}
if (dwRead) {
WriteFile(hCurrentHandle, buf, dwRead, &dwRead, NULL);
}
if (WAIT_TIMEOUT != WaitForSingleObject(pi.hThread, 10)) {
break;
}
}
CloseHandle(pi.hProcess);
CloseHandle(pi.hThread);
MessageBoxA(NULL, "Application Quit", "", MB_OK);
}
CloseHandle(hChildInReadPipe);
CloseHandle(hChildInWritePipe);
}
CloseHandle(hChildOutReadPipe);
CloseHandle(hChildOutWritePipe);
}
}
if (pszArgv) LocalFree(pszArgv);
return 0;
}
In the code, we create two pairs of pipes. One pair we use as stdin and another as stdout. We pass one pipe from the pair into the child process which will be output as stdout, the second pipe from it we will be using for reading in the parent process. In the sample, we check periodically if any data is available. And, in case of new data, perform reading it and output into the console. The result of execution of this code is the same as in the previous example.
The implementation of the same scenario in .NET looks much simpler compared to C++ code.
AllocConsole();
var info = new ProcessStartInfo(Application.ExecutablePath, "child");
info.UseShellExecute = false;
info.RedirectStandardOutput = true;
var process = Process.Start(info);
if (process != null)
{
process.OutputDataReceived += Child_OutputDataReceived;
process.BeginOutputReadLine();
process.WaitForExit();
process.Dispose();
MessageBox.Show("Application Quit");
}
In the code, to initiate the child process, we are using the ProcessStartInfo structure and setting the RedirectStandardOutput property value to true. Once the process object is created, it’s required to set the OutputDataReceived event handler and call BeginOutputReadLine method to start receiving data.
static void Child_OutputDataReceived(object sender, DataReceivedEventArgs e)
{
Console.WriteLine(e.Data);
}
On the callback, we just write what we receive into the previously allocated console window. Finally, we got the same output as in previous examples, but if this code started under Visual Studio, then it displayed messages in the output window.
In some cases, it is not possible to have a console view, or not possible to launch a process as a child - for example, if we have Windows Service or even Kernel Driver. In such cases, there is another easy way for providing live data of the application workflow. That is usage of Debug API. This method works for both console and window applications, also suitable for Windows services. In the application, that is done by OutputDebugString API usage.
#include <stdio.h>
#include <windows.h>
int WINAPI WinMain(HINSTANCE hInstance, HINSTANCE hPrevInstance,
LPSTR lpCmdLine, int nCmdShow)
{
OutputDebugStringW(L"This is application workflow message\n");
MessageBoxA(NULL,"Application Quit","",MB_OK);
}
The text which is output with this API display in attached debuggers output window:
An OutputDebugString API can be easily called from .NET.
using System.Runtime.InteropServices;
using System.Windows.Forms;
class Program
{
[DllImport("kernel32.dll", EntryPoint = "OutputDebugStringW",
CharSet = CharSet.Unicode)]
static extern void OutputDebugString(string _text);
static void Main(string[] args)
{
OutputDebugString("This is application workflow message\n");
MessageBox.Show("Application Quit");
}
}
.NET also has another ability to output trace information into the attached debugger. That is involved in the System.Diagnostics namespace. There are two classes which are allowed to provide output text for the debugger: class Trace - output text under debug build or once TRACE defined and class Debug which outputs data only under debug build or once it has DEBUG definition.
static void Main(string[] args)
{
System.Diagnostics.Trace.WriteLine(
"This is a trace message");
System.Diagnostics.Debug.WriteLine(
"This message displayed under debug configuration only");
MessageBox.Show("Application Quit");
}
You can see the result execution under debug build on output:
You may ask questions like: what is the benefit of the usage OutputDebugString API directly if the platform already has classes which are designed for that purpose. Let's compare performance of the execution output in these two ways with the next code:
[DllImport("kernel32.dll",
EntryPoint = "OutputDebugStringW", CharSet = CharSet.Unicode)]
static extern void OutputDebugString(string _text);
static void Main(string[] args)
{
int iterations = 100;
long elapsed_trace = 0;
long elapsed_output = 0;
{
int idx = 0;
long start = System.Diagnostics.Stopwatch.GetTimestamp();
while (idx < iterations)
{
System.Diagnostics.Trace.WriteLine(
string.Format("This is a trace message {0}",++idx));
}
elapsed_trace = System.Diagnostics.Stopwatch.GetTimestamp();
elapsed_trace -= start;
}
{
int idx = 0;
long start = System.Diagnostics.Stopwatch.GetTimestamp();
while (idx < iterations)
{
OutputDebugString(
string.Format("This is a output debug message {0}\n",++idx));
}
elapsed_output = System.Diagnostics.Stopwatch.GetTimestamp();
elapsed_output -= start;
}
Console.WriteLine("Time Measurments in Seconds Trace: {0} Output: {1}",
elapsed_trace * 1.0 / System.Diagnostics.Stopwatch.Frequency,
elapsed_output * 1.0 / System.Diagnostics.Stopwatch.Frequency);
Console.ReadKey();
}
Well, from the code above, you can see that we measure timings of 100 iterations with the trace printing and usage debug output API. We save start timings and calculate elapsed time after the loop finished. The result of the execution is next:
As you can see - the usage of .NET trace calls is very slow. In case of large execution in your application, you can go out for a coffee while it is processing. Of course, it is fine to use trace class for outputting some messages in non performance critical parts or if you like coffee.
Another good question - we can see our text messages only on the output window under debugger, so, how can we determine what is happening on a user PC? Do we need to install Visual Studio or any other debugger to capture outputs? The answer is - no. One good tool which can be used for that is the DbgView tool from sysinternals.
The DbgView tool properly prints outputs from the performance comparison .NET application example above, just don’t forget to run the program executable file directly, not under Visual Studio.
As you can see, the .NET Trace class works much better to output from an application into DbgView tool instead of running under Visual Studio.
The .NET Trace class performs output information to the specified listener objects and one of them is the debugger output. Accessing the collection of the listeners causes such latency. But we can add our own listener instance which can perform any additional functionality, such as file saving. Basic our own listener implementation looks next:
class MyListener : TraceListener
{
public override void Write(string message)
{
OutputDebugString(message);
}
public override void WriteLine(string message)
{
Write((string.IsNullOrEmpty(message) ? "" : message) + "\n");
}
}
In initial listener collection, we remove all existing objects and add new instance of our own implementation:
System.Diagnostics.Trace.Listeners.Clear();
System.Diagnostics.Trace.Listeners.Add(new MyListener());
System.Diagnostics.Trace.WriteLine("This is a trace message");
So, the text output in the example above will be passed to our object. That you can see if you set the breakpoint in the Write method like in the screenshot below:
.NET has a special trace listener class ConsoleTraceListener which passes the data to the stderr or stdout.
Another class in .NET for output is the trace information into debugger. It's the static class: System.Diagnostics.Debugger.
Debugger.Log(0, "Info",string.Format("This is a Debugger.Log message {0}\n", ++idx));
In the time measurement execution sample, we can add that Debugger class calls to see if we get better performance:
The debug output is thread safety. That we can check by starting several threads in our application. All those threads will output text with OutputDebugString API.
int WINAPI WinMain(HINSTANCE hInstance, HINSTANCE hPrevInstance,
LPSTR lpCmdLine, int nCmdShow)
{
g_evQuit = CreateEvent(NULL,TRUE,FALSE,NULL);
int threads = 100;
HANDLE * processes = (HANDLE *)malloc(threads * sizeof(HANDLE));
for (int i = 0; i < threads; i++) {
processes[i] = CreateThread(NULL, 0, ProcessThread, NULL, 0, NULL);
}
Sleep(5000);
SetEvent(g_evQuit);
for (int i = 0; i < threads; i++) {
WaitForSingleObject(processes[i], INFINITE);
CloseHandle(processes[i]);
}
free(processes);
CloseHandle(g_evQuit);
MessageBoxA(NULL,"Application Quit","",MB_OK);
}
And the ProcessThread function implementation:
DWORD WINAPI ProcessThread(PVOID p)
{
UNREFERENCED_PARAMETER(p);
srand(GetTickCount());
int period = rand() * 300 / RAND_MAX;
DWORD id = GetCurrentThreadId();
WCHAR szTemp[200] = {0};
while (TRUE) {
swprintf_s(szTemp,L"Hello from thread: %d\n",id);
OutputDebugStringW(szTemp);
if (WAIT_OBJECT_0 == WaitForSingleObject(g_evQuit,period)) break;
}
return 0;
}
You can start the application under debugger or separately. In the received results, there are no broken messages appearing in the output.
The .NET implementation of the same functionality with the Trace.WriteLine calls also works well.
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Threading;
using System.Windows.Forms;
class Program
{
static void ProcessThread()
{
var rand = new Random();
int id = Thread.CurrentThread.ManagedThreadId;
int period = rand.Next(1, 300);
do
{
Trace.WriteLine(string.Format("Hello From thread {0}", id));
}
while (!g_evQuit.WaitOne(period));
}
static EventWaitHandle g_evQuit =
new EventWaitHandle(false, EventResetMode.ManualReset);
static void Main(string[] args)
{
List<Thread> threads = new List<Thread>();
while (threads.Count < 100)
{
threads.Add(new Thread(ProcessThread));
}
foreach (var t in threads) { t.Start(); }
Thread.Sleep(5000);
g_evQuit.Set();
while (threads.Count > 0)
{
threads[0].Join();
threads.RemoveAt(0);
}
MessageBox.Show("Application Quit");
}
}
But if you use the Debugger.Log call instead, then you will get broken messages. Which means that the Debugger.Log call is not thread safe. This is because that method split each output into separate strings.
Let’s look at how we can receive data which was sent with the previously described methods. Output debug information internally raises an exception which can be received by the attached debugger. An exception is thrown every time API calls and if a debugger is attached, it is notified that the debug text appears. In the system, we have the IsDebuggerPresent API which allows us to determine if our application is running under debugger or not. It is possible to call OutputDebugString API only if the application is running under debugger to avoid any delays.
if (IsDebuggerPresent()) {
OutputDebugStringW(L"This message sent if affplication under debugger\n");
}
This API can be simply imported into .NET:
[DllImport("kernel32.dll")]
[return: MarshalAs(UnmanagedType.Bool)]
static extern bool IsDebuggerPresent();
static void Main(string[] args)
{
if (IsDebuggerPresent())
{
Console.WriteLine("We Under Debugger");
}
Console.ReadKey();
}
The code above displays text if we start an application from Visual Studio. In .NET, we also have a static class Debugger with the IsAttached property which also allows us to determine that we are under debugging:
if (System.Diagnostics.Debugger.IsAttached)
{
Console.WriteLine("We Under Debugger");
}
As mentioned earlier, current implementation of debugger string output API is done by raising the special system exception. There are two different exceptions for output debug strings. The old one is DBG_PRINTEXCEPTION_C (0x40010006) which supports only ANSI strings input. And the exception with support of the Unicode string is DBG_PRINTEXCEPTION_WIDE_C (0x4001000A). Let's try to implement our own debugger string output in the same way and see how it works.
void MyOutputDebugStringW(LPCWSTR pszText) {
if (pszText && wcslen(pszText)) {
size_t cch = wcslen(pszText) + 1;
char * text = (char *)malloc(cch << 1);
if (text) {
__try {
memset(text, 0x00, cch);
size_t c = 0;
wcstombs_s(&c, text, cch << 1, pszText, cch - 1);
ULONG_PTR args[] = {
cch,(ULONG_PTR)pszText,cch,(ULONG_PTR)text
};
__try {
RaiseException(DBG_PRINTEXCEPTION_WIDE_C,
0, _countof(args), args);
}
__except (EXCEPTION_EXECUTE_HANDLER) {
}
}
__finally {
free(text);
}
}
}
}
We are raising DBG_PRINTEXCEPTION_WIDE_C which is required to pass two different strings Ansi and Unicode. The DBG_PRINTEXCEPTION_C only requires the Ansi string argument. Which string will be provided to the debugger depends on the API it uses.
The main function implementation which calls our function.
int WINAPI WinMain(HINSTANCE hInstance, HINSTANCE hPrevInstance,
LPSTR lpCmdLine, int nCmdShow)
{
MyOutputDebugStringW(
L"This text provided with own implementation of debug string output\n");
MessageBoxA(NULL,"Application Quit","",MB_OK);
}
The implementation can be imported into .NET with the PInvoke:
[DllImport("kernel32.dll")]
static extern void RaiseException(
[MarshalAs(UnmanagedType.U4)] int dwExceptionCode,
[MarshalAs(UnmanagedType.U4)] int dwExceptionFlags,
[MarshalAs(UnmanagedType.U4)] int nNumberOfArguments,
[MarshalAs(UnmanagedType.LPArray,
ArraySubType = UnmanagedType.SysInt, SizeParamIndex =2)]
IntPtr[] lpArguments
);
const int DBG_PRINTEXCEPTION_WIDE_C = 0x4001000A;
static void MyOutputDebugString(string text)
{
if (string.IsNullOrEmpty(text)) return;
var unicode = Encoding.Unicode.GetBytes(text);
var ansi = Encoding.Convert(Encoding.Unicode, Encoding.Default, unicode);
IntPtr[] args = new IntPtr[4];
args[0] = new IntPtr(text.Length + 1);
args[1] = Marshal.AllocCoTaskMem(unicode.Length + 2);
args[2] = new IntPtr(ansi.Length + 1);
args[3] = Marshal.AllocCoTaskMem(ansi.Length + 1);
Marshal.Copy(unicode, 0, args[1], unicode.Length);
Marshal.Copy(ansi, 0, args[3], ansi.Length);
try
{
RaiseException(DBG_PRINTEXCEPTION_WIDE_C,0, args.Length, args);
}
catch
{
}
Marshal.FreeCoTaskMem(args[1]);
Marshal.FreeCoTaskMem(args[3]);
}
If we launch the code above from Visual Studio, then we can see the text in the output window:
The exception which was thrown by OutputDebugString can be received by the debugger application using WaitForDebugEvent API. That function handles receiving Ansi strings. To allow receiving Unicode debug strings necessary to use WaitForDebugEventEx API. Those two functions have the same arguments. The exception debugger output also has some latency as the debugger application once receives a message, stops execution until it processes the debug event and calls ContinueDebugEvent API. That's why the debug output string is thread safe and the main debugger process receives all those messages.
As an example of handling output debug strings, we made an application which starts itself as a child process, and the main process attaches to it as a debugger. To determine that process started as a child, we will use command line arguments. The child process will perform output text with OutputDebugString API.
INT nArgs;
LPWSTR * pszArgv = CommandLineToArgvW(lpCmdLine, &nArgs);
if (pszArgv && nArgs >= 1 && _wcsicmp(pszArgv[0], L"child") == 0) {
int idx = 0;
while (idx++ < 100) {
TracePrint("Child Message #%d\n", idx);
Sleep(100);
}
}
And the TracePrint function is defined as follows:
void TracePrint(const char * format, ...) {
va_list args;
va_start(args, format);
int _length = _vscprintf(format, args) + 1;
char * _string = (char *)malloc(_length);
if (_string) {
memset(_string, 0, _length);
_vsprintf_p(_string, _length, format, args);
__try {
OutputDebugStringA(_string);
} __finally {
free(_string);
}
}
va_end(args);
}
To avoid any security configuration, we set the DEBUG_ONLY_THIS_PROCESS flag during process creation.
SECURITY_ATTRIBUTES sa = { 0 };
PROCESS_INFORMATION pi = { 0 };
STARTUPINFO si = { 0 };
WCHAR szPath[1024] = { 0 };
GetModuleFileNameW(NULL, szPath + 1, _countof(szPath) - 1);
szPath[0] = '\"';
wcscat_s(szPath, L"\" child");
sa.nLength = sizeof(SECURITY_ATTRIBUTES);
sa.bInheritHandle = TRUE;
sa.lpSecurityDescriptor = NULL;
si.cb = sizeof(STARTUPINFO);
CreateProcess(NULL, szPath, NULL, NULL, TRUE,
DEBUG_ONLY_THIS_PROCESS, NULL, NULL, &si, &pi);
After we start debugging the created process and process messages which produced WaitForDebugEvent API, we are interested in the OUTPUT_DEBUG_STRING_EVENT event only. Once it is received, we copy data from memory pointed in the OUTPUT_DEBUG_STRING_INFO structure of the debug event using ReadProcessMemory API.
char * p = nullptr;
size_t size = 0;
if (!DebugActiveProcess(pi.dwProcessId)) {
while (true) {
DEBUG_EVENT _event = { 0 };
if (!WaitForDebugEvent(&_event, INFINITE)) {
wprintf(L"WaitForDebugEvent Failed 0x%08x\n",GetLastError());
break;
}
if (_event.dwDebugEventCode == OUTPUT_DEBUG_STRING_EVENT) {
auto data = &_event.u.DebugString;
size_t cch = data->nDebugStringLength + 2;
if (cch > size) {
p = (char *)realloc(p,cch);
size = cch;
}
memset(p,0x00,size);
cch = data->nDebugStringLength;
if (data->fUnicode) cch *= 2;
if (ReadProcessMemory(pi.hProcess,
data->lpDebugStringData, p,
cch, &cch)
) {
wchar_t Format[200] = {0};
swprintf_s(Format,L"Process Output String: \"%%%s\"\n",
data->fUnicode ? L"s" : L"S");
if (data->fUnicode) {
wchar_t * pwsz = (wchar_t *)p;
while (wcslen(pwsz) && pwsz[wcslen(pwsz) - 1] == '\n') {
pwsz[wcslen(pwsz) - 1] = '\0';
}
}
else {
while (strlen(p) && p[strlen(p) - 1] == '\n') {
p[strlen(p) - 1] = '\0';
}
}
wprintf(Format,p);
} else {
wprintf(L"ReadProcessMemory Failed 0x%08x\n",GetLastError());
}
}
ContinueDebugEvent(_event.dwProcessId,_event.dwThreadId,DBG_CONTINUE);
if (WAIT_TIMEOUT != WaitForSingleObject(pi.hThread, 10)) {
break;
}
}
DebugActiveProcessStop(pi.dwProcessId);
} else {
wprintf(L"DebugActiveProcess Failed 0x%08x\n",GetLastError());
}
if (p) free(p);
Once we get debug output text, we print it into the console. Then, we call ContinueDebugEvent API to continue the process execution and wait for the next event. The result of program execution is displayed in the below screenshot:
The .NET is not allowed to do the same in a simple way, but it is also possible to have such functionality with PInvoke. Child process just like in previous similar implementations just calls the OutputDebugString API in the loop.
if (args.Length >= 1 && args[0].ToLower() == "child")
{
int idx = 0;
while (idx++ < 100) {
OutputDebugString(string.Format("Child Message #{0}", idx));
Thread.Sleep(100);
}
}
The main functionality is in the main process, and it looks similar to C++ implementation due to it containing native API calls.
AllocConsole();
var info = new ProcessStartInfo(Application.ExecutablePath, "child");
info.UseShellExecute = false;
var process = Process.Start(info);
if (process != null) {
if (DebugActiveProcess(process.Id)) {
while (true) {
DEBUG_EVENT _event;
if (!WaitForDebugEvent(out _event, -1)) {
break;
}
if (_event.dwDebugEventCode == OUTPUT_DEBUG_STRING_EVENT) {
int cb = (_event.nDebugStringLength + 1) << 1;
IntPtr p = Marshal.AllocCoTaskMem(cb);
if (p != IntPtr.Zero) {
try {
cb = _event.nDebugStringLength;
if (_event.fUnicode != 0) cb *= 2;
if (ReadProcessMemory(process.Handle,
_event.lpDebugStringData, p, cb, out cb)) {
Console.WriteLine(
"Process Output String: \"{0}\"",
_event.fUnicode != 0 ?
Marshal.PtrToStringUni(p) : Marshal.PtrToStringAnsi(p));
} else {
Console.WriteLine("ReadProcessMemory Failed 0x{0:x8}\n",
GetLastError());
}
}
finally {
Marshal.FreeCoTaskMem(p);
}
}
}
ContinueDebugEvent(_event.dwProcessId, _event.dwThreadId, DBG_CONTINUE);
if (process.WaitForExit(10)) {
break;
}
}
DebugActiveProcessStop(process.Id);
}
else {
Console.WriteLine("DebugActiveProcess Failed {0:x8}\n", GetLastError());
}
if (!process.HasExited)
{
process.Kill();
}
process.Dispose();
MessageBox.Show("Application Quit");
}
Only interesting thing here is the WaitForDebugEvent function and DEBUG_EVENT structure. This structure has a union with the different structure arguments depending on the event code. As this structure is allocated by the caller, we need to handle it with enough size in function call wrapper. This can be done with allocating memory and passing it as IntPtr argument to the WaitForDebugEvent function, and later performing marshaling from pointer to structure DEBUG_EVENT. Or set up enough size in the structure itself and let it perform marshaling automatically. Initially, I made the first way and later I changed it, as I thought that it would look better.
[StructLayout(LayoutKind.Sequential)]
struct DEBUG_EVENT
{
[MarshalAs(UnmanagedType.U4)]
public int dwDebugEventCode;
[MarshalAs(UnmanagedType.U4)]
public int dwProcessId;
[MarshalAs(UnmanagedType.U4)]
public int dwThreadId;
public IntPtr lpDebugStringData;
[MarshalAs(UnmanagedType.U2)]
public ushort fUnicode;
[MarshalAs(UnmanagedType.U2)]
public ushort nDebugStringLength;
[MarshalAs(UnmanagedType.ByValArray,SizeConst = 144)]
public byte[] Reserved;
}
As you can see in the DEBUG_EVENT, we handle only debug text information from the OUTPUT_DEBUG_STRING_INFO structure. For other union structures, we add the padding array of bytes, so we are able to pass the structure directly in the WaitForDebugEvent API.
[DllImport("kernel32.dll", CallingConvention = CallingConvention.StdCall,
SetLastError = true)]
[return: MarshalAs(UnmanagedType.Bool)]
static extern bool WaitForDebugEvent(
[Out] out DEBUG_EVENT lpDebugEvent,
[In, MarshalAs(UnmanagedType.U4)] int dwMilliseconds
);
The output of the application is the same as in C++ version.
If we launch a compiled version of the executable which outputs a string by raising an exception method and without a debugger attached, then we will not be able to see output messages which are provided with the above method by just raising the specific exception. But if you use a particular OutputDebugString API, then you can see the output text in DbgView tool. That tool is not attached as a debugger to the application. This means that if no debugger is attached, then the OutputDebugString API works in a different way.
That way has already been described many times, but I will also mention it here briefly. The OutputDebugString API internally opens the special mutex with the name DBWinMutex. By locking that mutex application opens other shared objects: two events and shared memory. After application writes output string into shared memory with name DBWIN_BUFFER, while doing that, it also waits for buffer shared event DBWIN_BUFFER_READY and once text is written, it signals the DBWIN_DATA_READY shared event. Those named objects you can see in the Process Explorer tool (ProcExp) from sysinternals. We have internally two waiting operations which can cause little latency.
The sample of implementation providing system wide text messages based on algorithm description above is next.
HANDLE hMutex = OpenMutexW(READ_CONTROL | SYNCHRONIZE |
MUTEX_MODIFY_STATE, TRUE,L"DBWinMutex");
if (!hMutex) {
CreateSecurityDescriptor();
SECURITY_ATTRIBUTES sa = { 0 };
sa.nLength = sizeof(sa);
sa.bInheritHandle = FALSE;
sa.lpSecurityDescriptor = (LPVOID)g_pSecurityDescriptor;
hMutex = CreateMutexExW(&sa, L"DBWinMutex", 0,
MAXIMUM_ALLOWED | SYNCHRONIZE | READ_CONTROL | MUTEX_MODIFY_STATE);
}
if (hMutex) {
HANDLE hMap = NULL;
HANDLE hBufferReady = NULL;
HANDLE hDataReady = NULL;
DWORD result = WaitForSingleObject(hMutex, 10000);
if (result == WAIT_OBJECT_0) {
__try {
hMap = OpenFileMappingW(FILE_MAP_WRITE, FALSE, L"DBWIN_BUFFER");
hBufferReady = OpenEventW(SYNCHRONIZE, FALSE, L"DBWIN_BUFFER_READY");
hDataReady = OpenEventW(EVENT_MODIFY_STATE, FALSE, L"DBWIN_DATA_READY");
}
__finally {
if (!hDataReady) {
ReleaseMutex(hMutex);
}
}
__try {
LPVOID pBuffer = NULL;
if (hMap && hBufferReady && hDataReady) {
pBuffer = MapViewOfFile(hMap, SECTION_MAP_WRITE |
SECTION_MAP_READ, 0, 0, 0);
}
if (pBuffer) {
cch = strlen(text) + 1;
char * p = text;
while (cch > 0) {
size_t length = 4091;
if (cch < length) {
length = cch;
}
if (WAIT_OBJECT_0 == WaitForSingleObject(hBufferReady, 10000)) {
*((DWORD*)pBuffer) = (DWORD)GetCurrentProcessId();
memcpy((PUCHAR)pBuffer + sizeof(DWORD), p, length);
if (length == 4091) ((PUCHAR)pBuffer)[4095] = '\0';
SetEvent(hDataReady);
}
else {
break;
}
cch -= length;
p += length;
}
UnmapViewOfFile(pBuffer);
}
}
__finally {
if (hBufferReady) CloseHandle(hBufferReady);
if (hDataReady) {
CloseHandle(hDataReady);
ReleaseMutex(hMutex);
}
if (hMap) CloseHandle(hMap);
}
}
CloseHandle(hMutex);
FreeSecurityDescriptor();
}
Add that implementation into our own debug output string described previously and start the application not under Visual Studio. In the DbgView tool, you can see the output of our text.
Based on those descriptions, we can create fully functional our own OutputDebugString API.
The main issue in the implementation is the security of opening shared mutex, as OutputDebugString API can be called from non admin users.
This implementation can also easily be done in .NET. The first step is opening the mutex object.
Mutex mutex = null;
if (!Mutex.TryOpenExisting("DBWinMutex",
MutexRights.Synchronize | MutexRights.ReadPermissions |
MutexRights.Modify, out mutex))
{
bool bCreateNew;
MutexSecurity security = new MutexSecurity();
string CurrentUser = Environment.UserDomainName + "\\" + Environment.UserName;
security.AddAccessRule(new MutexAccessRule(
CurrentUser, MutexRights.Synchronize | MutexRights.Modify,
AccessControlType.Allow));
security.AddAccessRule(new MutexAccessRule(
new SecurityIdentifier("S-1-1-0"), MutexRights.Synchronize | MutexRights.Modify,
AccessControlType.Allow));
security.AddAccessRule(new MutexAccessRule(
new SecurityIdentifier("S-1-5-18"),
MutexRights.ReadPermissions | MutexRights.Modify,
AccessControlType.Allow));
security.AddAccessRule(new MutexAccessRule(
new SecurityIdentifier("S-1-5-32-544"),
MutexRights.ReadPermissions | MutexRights.Modify,
AccessControlType.Allow));
mutex = new Mutex(false, "DBWinMutex", out bCreateNew, security);
}
Next is the opening shared objects.
EventWaitHandle DataReady = null;
EventWaitHandle BufferReady = null;
MemoryMappedFile MappedFile = null;
MemoryMappedViewAccessor Accessor = null;
if (EventWaitHandle.TryOpenExisting("DBWIN_BUFFER_READY",
EventWaitHandleRights.Synchronize, out BufferReady))
{
if (EventWaitHandle.TryOpenExisting("DBWIN_DATA_READY",
EventWaitHandleRights.Modify, out DataReady))
{
try
{
MappedFile = MemoryMappedFile.OpenExisting
("DBWIN_BUFFER", MemoryMappedFileRights.Write);
}
catch
{
}
}
}
if (MappedFile != null) {
Accessor = MappedFile.CreateViewAccessor(0, 0, MemoryMappedFileAccess.ReadWrite);
}
Wait for buffer ready event signal and write data.
int offset = 0;
int count = 4091;
while (ansi.Length - offset > 0)
{
if (count > ansi.Length - offset) count = ansi.Length - offset;
if (BufferReady.WaitOne(10000))
{
Accessor.Write(0, PID);
Accessor.WriteArray<byte>(4, ansi, offset, count);
Accessor.Write(count + 4, 0);
DataReady.Set();
}
else
{
break;
}
offset += count;
}
Clean up objects.
if (Accessor != null) Accessor.Dispose();
if (BufferReady != null) BufferReady.Dispose();
if (DataReady != null) DataReady.Dispose();
if (MappedFile != null) MappedFile.Dispose();
if (mutex != null)
{
mutex.ReleaseMutex();
mutex.Dispose();
}
Result of function call you also can see in the DbgView application.
Now it’s time to implement the receiving part. Receiving shared strings output can be done in a backward way. Initially, we open shared objects but with different access requests, as now we need to wait for the DBWIN_DATA_READY event to be signalled and reset the DBWIN_BUFFER_READY event once we are done. As you can see in the previous implementation, we are opening existing shared objects. This is done as if there is no application which is waiting for the data, then we just skip sending. So the receiver part should create instances of those objects in case they failed to be opened.
hMap = OpenFileMappingW(FILE_MAP_READ, FALSE, L"DBWIN_BUFFER");
if (!hMap) {
hMap = CreateFileMappingW(INVALID_HANDLE_VALUE,&sa,
PAGE_READWRITE,0,0x1000,L"DBWIN_BUFFER");
if (hMap == INVALID_HANDLE_VALUE) {
hMap = NULL;
}
}
hBufferReady = OpenEventW(EVENT_MODIFY_STATE, FALSE, L"DBWIN_BUFFER_READY");
if (!hBufferReady) {
hBufferReady = CreateEventW(&sa,FALSE,FALSE,L"DBWIN_BUFFER_READY");
if (hBufferReady == INVALID_HANDLE_VALUE) {
hBufferReady = NULL;
}
}
hDataReady = OpenEventW(SYNCHRONIZE, FALSE, L"DBWIN_DATA_READY");
if (!hDataReady) {
bCreated = TRUE;
hDataReady = CreateEventW(&sa,FALSE,FALSE,L"DBWIN_DATA_READY");
if (hDataReady == INVALID_HANDLE_VALUE) {
hDataReady = NULL;
}
}
Next in a loop, we wait for the event and read the data from the mapped shared section. Section can be mapped for reading access only, as we do not write any data.
LPVOID pBuffer = MapViewOfFile(hMap, SECTION_MAP_READ, 0, 0, 0);
HANDLE hHandles[] = { hDataReady,g_hQuit };
while (true) {
if (WAIT_OBJECT_0 == WaitForMultipleObjects(
_countof(hHandles), hHandles, FALSE, INFINITE)) {
DWORD ProcessId = *((PDWORD)pBuffer);
strncpy_s(text, cch, (char*)pBuffer + 4, cch - 4);
SetEvent(hBufferReady);
if (strlen(text)) {
while (text[strlen(text) - 1] == '\n') {
text[strlen(text) - 1] = '\0';
}
printf("[%d] %s\n", ProcessId, text);
}
}
else {
break;
}
}
UnmapViewOfFile(pBuffer);
To test, we can start the previous code sample which writes output debug strings in with several threads along with our current receiver implementation and checks the result.
We can do the same way in .NET. First, open or create the mutex object.
Mutex mutex = null;
if (!Mutex.TryOpenExisting("DBWinMutex", MutexRights.Synchronize
| MutexRights.ReadPermissions | MutexRights.Modify, out mutex))
{
bool bCreateNew;
MutexSecurity security = new MutexSecurity();
string CurrentUser = Environment.UserDomainName + "\\" + Environment.UserName;
security.AddAccessRule(new MutexAccessRule(
CurrentUser, MutexRights.Synchronize | MutexRights.Modify,
AccessControlType.Allow));
security.AddAccessRule(new MutexAccessRule(
new SecurityIdentifier("S-1-1-0"),
MutexRights.Synchronize | MutexRights.Modify,
AccessControlType.Allow));
security.AddAccessRule(new MutexAccessRule(
new SecurityIdentifier("S-1-5-18"),
MutexRights.ReadPermissions | MutexRights.Modify,
AccessControlType.Allow));
security.AddAccessRule(new MutexAccessRule(
new SecurityIdentifier("S-1-5-32-544"),
MutexRights.ReadPermissions | MutexRights.Modify,
AccessControlType.Allow));
mutex = new Mutex(false, "DBWinMutex", out bCreateNew, security);
}
After opening or creating shared objects:
EventWaitHandle DataReady = null;
EventWaitHandle BufferReady = null;
MemoryMappedFile MappedFile = null;
MemoryMappedViewAccessor Accessor = null;
MemoryMappedFileSecurity memory_security = new MemoryMappedFileSecurity();
EventWaitHandleSecurity event_security = new EventWaitHandleSecurity();
memory_security.AddAccessRule(new AccessRule<MemoryMappedFileRights>(
new SecurityIdentifier("S-1-1-0"), MemoryMappedFileRights.ReadWrite,
AccessControlType.Allow));
event_security.AddAccessRule(new EventWaitHandleAccessRule(
new SecurityIdentifier("S-1-1-0"),
EventWaitHandleRights.Synchronize |
EventWaitHandleRights.Modify | EventWaitHandleRights.ReadPermissions,
AccessControlType.Allow));
if (!EventWaitHandle.TryOpenExisting("DBWIN_BUFFER_READY",
EventWaitHandleRights.Modify, out BufferReady))
{
BufferReady = new EventWaitHandle(false, EventResetMode.AutoReset,
"DBWIN_BUFFER_READY", out bCreateNew, event_security);
}
if (!EventWaitHandle.TryOpenExisting("DBWIN_DATA_READY",
EventWaitHandleRights.Synchronize, out DataReady))
{
DataReady = new EventWaitHandle(false, EventResetMode.AutoReset,
"DBWIN_DATA_READY", out bCreateNew, event_security);
}
try
{
MappedFile = MemoryMappedFile.OpenExisting
("DBWIN_BUFFER", MemoryMappedFileRights.Read);
}
catch
{
}
if (MappedFile == null)
{
MappedFile = MemoryMappedFile.CreateOrOpen("DBWIN_BUFFER", cch,
MemoryMappedFileAccess.ReadWrite,
MemoryMappedFileOptions.None, memory_security,
System.IO.HandleInheritability.None);
}
if (MappedFile != null)
{
Accessor = MappedFile.CreateViewAccessor(0, 0, MemoryMappedFileAccess.Read);
}
Processing notifications in a loop and output messages to the console window.
while (true)
{
if (0 == WaitHandle.WaitAny(new WaitHandle[] { DataReady, g_evQuit }))
{
int ProcessId = Accessor.ReadInt32(0);
Accessor.ReadArray<byte>(4, text, 0, text.Length - 4);
BufferReady.Set();
int length = 0;
while (length < text.Length && text[length] != '\0') length++;
string ansi_text = Encoding.Default.GetString(text, 0, length);
if (!string.IsNullOrEmpty(ansi_text))
{
if (ansi_text[ansi_text.Length - 1] == '\n')
ansi_text = ansi_text.Remove(ansi_text.Length - 1,1);
Console.WriteLine("[{0}] {1}", ProcessId, ansi_text);
}
}
else
{
break;
}
}
Result of execution is the same as in C++ application version.
There will be concurrency in case two instances of the receiver applications are running. So the messages can be received by one application only as in implementation auto reset events are used for synchronization. Due to that reason, the DbgView application blocks receiving data in its second instance.
History
- 18th May, 2023: Initial version
