1 : // Copyright 2012 Google Inc. All Rights Reserved.
2 : //
3 : // Licensed under the Apache License, Version 2.0 (the "License");
4 : // you may not use this file except in compliance with the License.
5 : // You may obtain a copy of the License at
6 : //
7 : // http://www.apache.org/licenses/LICENSE-2.0
8 : //
9 : // Unless required by applicable law or agreed to in writing, software
10 : // distributed under the License is distributed on an "AS IS" BASIS,
11 : // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12 : // See the License for the specific language governing permissions and
13 : // limitations under the License.
14 : //
15 : // This file defines the trace::logger::Logger class which implements the
16 : // Logger RPC interface.
17 :
18 : #include "syzygy/trace/logger/logger.h"
19 :
20 : #include <windows.h> // NOLINT
21 : #include <dbghelp.h>
22 :
23 : #include "base/bind.h"
24 : #include "base/string_util.h"
25 : #include "base/stringprintf.h"
26 : #include "base/win/scoped_handle.h"
27 : #include "sawbuck/common/com_utils.h"
28 : #include "syzygy/trace/rpc/rpc_helpers.h"
29 :
30 : namespace trace {
31 : namespace logger {
32 :
33 : namespace {
34 :
35 : using trace::client::GetInstanceString;
36 :
37 : // A helper class to manage a SYMBOL_INFO structure.
38 : template <size_t max_name_len>
39 : class SymbolInfo {
40 : public:
41 E : SymbolInfo() {
42 : COMPILE_ASSERT(max_name_len > 0, error_maximum_name_length_is_zero);
43 : COMPILE_ASSERT(
44 : sizeof(buf_) - sizeof(info_) >= max_name_len * sizeof(wchar_t),
45 : error_not_enough_buffer_space_for_max_name_len_wchars);
46 :
47 E : ::memset(buf_, 0, sizeof(buf_));
48 E : info_.SizeOfStruct = sizeof(info_);
49 E : info_.MaxNameLen = max_name_len;
50 E : }
51 :
52 E : PSYMBOL_INFO Get() { return &info_; }
53 :
54 E : PSYMBOL_INFO operator->() { return &info_; }
55 :
56 : private:
57 : // SYMBOL_INFO is a variable length structure ending with a string (the
58 : // name of the symbol). The SYMBOL_INFO struct itself only declares the
59 : // first byte of the Name array, the rest we reserve by holding it in
60 : // union with a properly sized underlying buffer.
61 : union {
62 : SYMBOL_INFO info_;
63 : char buf_[sizeof(SYMBOL_INFO) + max_name_len * sizeof(wchar_t)];
64 : };
65 : };
66 :
67 : void GetSymbolInfo(HANDLE process,
68 : DWORD frame_ptr,
69 : std::string* name,
70 E : DWORD64* offset) {
71 E : DCHECK(frame_ptr != NULL);
72 E : DCHECK(name != NULL);
73 E : DCHECK(offset != NULL);
74 :
75 : // Constants we'll need later.
76 : static const size_t kMaxNameLength = 256;
77 E : SymbolInfo<kMaxNameLength> symbol;
78 :
79 : // Lookup the symbol by address.
80 E : if (::SymFromAddr(process, frame_ptr, offset, symbol.Get())) {
81 E : *name = symbol->Name;
82 E : } else {
83 i : *name = "(unknown)";
84 : }
85 E : }
86 :
87 E : void GetLineInfo(HANDLE process, DWORD_PTR frame, std::string* line_info) {
88 E : DCHECK(frame != NULL);
89 E : DCHECK(line_info != NULL);
90 :
91 E : DWORD line_displacement = 0;
92 E : IMAGEHLP_LINE64 line = {};
93 E : line.SizeOfStruct = sizeof(IMAGEHLP_LINE64);
94 E : if (::SymGetLineFromAddr64(process, frame, &line_displacement, &line))
95 E : base::SStringPrintf(line_info, "%s:%d", line.FileName, line.LineNumber);
96 E : else
97 E : line_info->clear();
98 E : }
99 :
100 : // A callback function used with the StackWalk64 function. It is called when
101 : // StackWalk64 needs to read memory from the address space of the process.
102 : // http://msdn.microsoft.com/en-us/library/windows/desktop/ms680559.aspx
103 : BOOL CALLBACK ReadProcessMemoryProc64(HANDLE process,
104 : DWORD64 base_address_64,
105 : PVOID buffer,
106 : DWORD size,
107 E : LPDWORD bytes_read) {
108 E : DCHECK(buffer != NULL);
109 E : DCHECK(bytes_read != NULL);
110 E : *bytes_read = 0;
111 E : LPCVOID base_address = reinterpret_cast<LPCVOID>(base_address_64);
112 E : if (::ReadProcessMemory(process, base_address, buffer, size, bytes_read))
113 E : return TRUE;
114 :
115 : // Maybe it was just a partial read, which isn't fatal.
116 i : DWORD error = ::GetLastError();
117 i : if (error == ERROR_PARTIAL_COPY)
118 i : return TRUE;
119 :
120 : // Nope, it was a real error.
121 i : LOG(ERROR) << "Failed to read process memory: " << com::LogWe(error) << ".";
122 i : return FALSE;
123 E : }
124 :
125 : } // namespace
126 :
127 : Logger::Logger()
128 : : trace::common::Service(L"Logger"),
129 E : destination_(NULL) {
130 E : }
131 :
132 E : Logger::~Logger() {
133 E : if (state() != kStopped) {
134 i : ignore_result(Stop());
135 i : ignore_result(Join());
136 : }
137 E : }
138 :
139 E : bool Logger::StartImpl() {
140 E : LOG(INFO) << "Starting the logging service.";
141 :
142 E : if (!InitRpc())
143 i : return false;
144 :
145 E : if (!StartRpc())
146 i : return false;
147 :
148 E : return true;
149 E : }
150 :
151 E : bool Logger::StopImpl() {
152 E : if (!StopRpc())
153 i : return false;
154 E : return true;
155 E : }
156 :
157 E : bool Logger::JoinImpl() {
158 : // Finish processing all RPC events. If Stop() has previously been called
159 : // this will simply ensure that all outstanding requests are handled. If
160 : // Stop has not been called, this will continue (i.e., block) handling events
161 : // until someone else calls Stop() in another thread.
162 E : if (!FinishRpc())
163 i : return false;
164 :
165 E : return true;
166 E : }
167 :
168 : bool Logger::AppendTrace(HANDLE process,
169 : const DWORD* trace_data,
170 : size_t trace_length,
171 E : std::string* message) {
172 E : DCHECK(trace_data != NULL);
173 E : DCHECK(message != NULL);
174 :
175 : // TODO(rogerm): Add an RPC session to the logger and its interface. This
176 : // would serialize calls per process and provide a convenient mechanism
177 : // for ensuring SymInitialize/Cleanup are called exactly once per client
178 : // process.
179 :
180 E : base::AutoLock auto_lock(symbol_lock_);
181 :
182 : // Initializes the symbols for the process:
183 : // - Defer symbol load until they're needed
184 : // - Use undecorated names
185 : // - Get line numbers
186 E : ::SymSetOptions(SYMOPT_DEFERRED_LOADS | SYMOPT_UNDNAME | SYMOPT_LOAD_LINES);
187 E : if (!::SymInitialize(process, NULL, TRUE)) {
188 i : DWORD error = ::GetLastError();
189 i : LOG(ERROR) << "SymInitialize failed: " << com::LogWe(error) << ".";
190 i : return false;
191 : }
192 :
193 : // Append each line of the trace to the message string.
194 E : for (size_t i = 0; i < trace_length; ++i) {
195 E : DWORD frame_ptr = trace_data[i];
196 E : DWORD64 offset = 0;
197 E : std::string symbol_name;
198 E : std::string line_info;
199 :
200 E : GetSymbolInfo(process, frame_ptr, &symbol_name, &offset);
201 E : GetLineInfo(process, frame_ptr, &line_info);
202 :
203 : base::StringAppendF(message,
204 : " #%d 0x%012llx in %s%s%s\n",
205 : i,
206 : frame_ptr + offset,
207 : symbol_name.c_str(),
208 : line_info.empty() ? "" : " ",
209 E : line_info.c_str());
210 E : }
211 :
212 E : if (!::SymCleanup(process)) {
213 i : DWORD error = ::GetLastError();
214 i : LOG(ERROR) << "SymCleanup failed: " << com::LogWe(error) << ".";
215 i : return false;
216 : }
217 :
218 E : return true;
219 E : }
220 :
221 : bool Logger::CaptureRemoteTrace(HANDLE process,
222 : CONTEXT* context,
223 E : std::vector<DWORD>* trace_data) {
224 E : DCHECK(context != NULL);
225 E : DCHECK(trace_data != NULL);
226 :
227 : // TODO(rogerm): Add an RPC session to the logger and its interface. This
228 : // would serialize calls per process and provide a convenient mechanism
229 : // for ensuring SymInitialize/Cleanup are called exactly once per client
230 : // process.
231 :
232 E : trace_data->clear();
233 E : trace_data->reserve(64);
234 :
235 E : base::AutoLock auto_lock(symbol_lock_);
236 :
237 : // Initializes the symbols for the process:
238 : // - Defer symbol load until they're needed
239 : // - Use undecorated names
240 : // - Get line numbers
241 E : ::SymSetOptions(SYMOPT_DEFERRED_LOADS | SYMOPT_UNDNAME | SYMOPT_LOAD_LINES);
242 E : if (!::SymInitialize(process, NULL, TRUE)) {
243 i : DWORD error = ::GetLastError();
244 i : LOG(ERROR) << "SymInitialize failed: " << com::LogWe(error) << ".";
245 i : return false;
246 : }
247 :
248 : // Initialize a stack frame structure.
249 : STACKFRAME64 stack_frame;
250 E : ::memset(&stack_frame, 0, sizeof(stack_frame));
251 : #if defined(_WIN64)
252 : int machine_type = IMAGE_FILE_MACHINE_AMD64;
253 : stack_frame.AddrPC.Offset = context->Rip;
254 : stack_frame.AddrFrame.Offset = context->Rbp;
255 : stack_frame.AddrStack.Offset = context->Rsp;
256 : #else
257 E : int machine_type = IMAGE_FILE_MACHINE_I386;
258 E : stack_frame.AddrPC.Offset = context->Eip;
259 E : stack_frame.AddrFrame.Offset = context->Ebp;
260 E : stack_frame.AddrStack.Offset = context->Esp;
261 : #endif
262 E : stack_frame.AddrPC.Mode = AddrModeFlat;
263 E : stack_frame.AddrFrame.Mode = AddrModeFlat;
264 E : stack_frame.AddrStack.Mode = AddrModeFlat;
265 :
266 : // Walk the stack.
267 : while (::StackWalk64(machine_type,
268 : process,
269 : NULL,
270 : &stack_frame,
271 : context,
272 : &ReadProcessMemoryProc64,
273 : &::SymFunctionTableAccess64,
274 : &::SymGetModuleBase64,
275 E : NULL)) {
276 E : trace_data->push_back(stack_frame.AddrPC.Offset);
277 E : }
278 :
279 E : if (!::SymCleanup(process)) {
280 i : DWORD error = ::GetLastError();
281 i : LOG(ERROR) << "SymCleanup failed: " << com::LogWe(error) << ".";
282 i : return false;
283 : }
284 :
285 : // And we're done.
286 E : return true;
287 E : }
288 :
289 E : bool Logger::Write(const base::StringPiece& message) {
290 E : if (message.empty())
291 i : return true;
292 :
293 E : base::AutoLock auto_lock(write_lock_);
294 :
295 : size_t chars_written = ::fwrite(message.data(),
296 : sizeof(std::string::value_type),
297 : message.size(),
298 E : destination_);
299 :
300 E : if (chars_written != message.size()) {
301 i : LOG(ERROR) << "Failed to write log message.";
302 i : return false;
303 : }
304 :
305 : if (message[message.size() - 1] != '\n' &&
306 E : ::fwrite("\n", 1, 1, destination_) != 1) {
307 i : LOG(ERROR) << "Failed to append trailing newline.";
308 i : return false;
309 : }
310 :
311 E : ::fflush(destination_);
312 :
313 E : return true;
314 E : }
315 :
316 : bool Logger::SaveMiniDump(HANDLE process,
317 : base::ProcessId pid,
318 : DWORD tid,
319 : DWORD exc_ptr,
320 E : DWORD flags) {
321 E : DCHECK(!minidump_dir_.empty());
322 :
323 : // Create a temporary file to which to write the minidump. We'll rename it
324 : // to something recognizable when we're finished writing to it.
325 E : base::FilePath temp_file_path;
326 E : if (!file_util::CreateTemporaryFileInDir(minidump_dir_, &temp_file_path)) {
327 i : LOG(ERROR) << "Could not create mini dump file in "
328 : << minidump_dir_.value();
329 i : return false;
330 : }
331 :
332 : {
333 : // Open the temp file in write mode. It will only stay open in this scope.
334 : // Outside of this scope, we'll access file by name.
335 : base::win::ScopedHandle temp_file(
336 : ::CreateFile(temp_file_path.value().c_str(), GENERIC_WRITE, 0, NULL,
337 E : CREATE_ALWAYS, FILE_ATTRIBUTE_NORMAL, NULL));
338 E : if (!temp_file.IsValid()) {
339 i : LOG(ERROR) << "Could not open mini dump file in "
340 : << minidump_dir_.value() << " for writing.";
341 i : return false;
342 : }
343 :
344 : // Access to ::MiniDumpWriteDump (and all DbgHelp functions) must be
345 : // serialized.
346 E : base::AutoLock auto_lock(symbol_lock_);
347 :
348 : // Generate the minidump.
349 : MINIDUMP_EXCEPTION_INFORMATION exc_info = {
350 E : tid, reinterpret_cast<EXCEPTION_POINTERS*>(exc_ptr), true };
351 : if (!::MiniDumpWriteDump(process, pid, temp_file, ::MiniDumpNormal,
352 E : &exc_info, NULL, NULL)) {
353 : // Note that the error set by ::MiniDumpWriteDump is an HRESULT, not a
354 : // Windows error. even though it is returned via ::GetLastError().
355 : // http://msdn.microsoft.com/en-us/library/windows/desktop/ms680360.aspx
356 i : HRESULT error = ::GetLastError();
357 i : LOG(ERROR) << "::MiniDumpWriteDump failed: " << com::LogHr(error) << ".";
358 i : return false;
359 : }
360 :
361 : // The temporary file is closed here, and the symbol lock released.
362 E : }
363 :
364 : // Rename the temporary file so that its recognizable as a dump.
365 : base::FilePath final_name(
366 : base::StringPrintf(L"minidump-%08u-%08u-%08u.dmp",
367 E : pid, tid, ::GetTickCount()));
368 E : if (!file_util::Move(temp_file_path, minidump_dir_.Append(final_name))) {
369 i : DWORD error = ::GetLastError();
370 i : LOG(ERROR) << "Failed to move dump file to final location "
371 : << com::LogWe(error) << ".";
372 i : return false;
373 : }
374 :
375 E : return true;
376 E : }
377 :
378 E : bool Logger::InitRpc() {
379 E : RPC_STATUS status = RPC_S_OK;
380 :
381 : // Initialize the RPC protocol we want to use.
382 E : std::wstring protocol(kLoggerRpcProtocol);
383 : std::wstring endpoint(
384 E : GetInstanceString(kLoggerRpcEndpointRoot, instance_id()));
385 :
386 E : VLOG(1) << "Initializing RPC endpoint '" << endpoint << "' "
387 : << "using the '" << protocol << "' protocol.";
388 : status = ::RpcServerUseProtseqEp(
389 : reinterpret_cast<RPC_WSTR>(&protocol[0]),
390 : RPC_C_LISTEN_MAX_CALLS_DEFAULT,
391 : reinterpret_cast<RPC_WSTR>(&endpoint[0]),
392 E : NULL /* Security descriptor. */);
393 E : if (status != RPC_S_OK && status != RPC_S_DUPLICATE_ENDPOINT) {
394 i : LOG(ERROR) << "Failed to init RPC protocol: " << com::LogWe(status) << ".";
395 i : return false;
396 : }
397 :
398 : // Register the logger interface.
399 E : VLOG(1) << "Registering the Logger interface.";
400 : status = ::RpcServerRegisterIf(
401 E : LoggerService_Logger_v1_0_s_ifspec, NULL, NULL);
402 E : if (status != RPC_S_OK) {
403 i : LOG(ERROR) << "Failed to register RPC interface: "
404 : << com::LogWe(status) << ".";
405 i : return false;
406 : }
407 :
408 : // Register the logger control interface.
409 E : VLOG(1) << "Registering the Logger Control interface.";
410 : status = ::RpcServerRegisterIf(
411 E : LoggerService_LoggerControl_v1_0_s_ifspec, NULL, NULL);
412 E : if (status != RPC_S_OK) {
413 i : LOG(ERROR) << "Failed to register RPC interface: "
414 : << com::LogWe(status) << ".";
415 i : return false;
416 : }
417 :
418 E : OnInitialized();
419 :
420 E : return true;
421 E : }
422 :
423 E : bool Logger::StartRpc() {
424 : // This method must be called by the owning thread, so no need to otherwise
425 : // synchronize the method invocation.
426 E : VLOG(1) << "Starting the RPC server.";
427 :
428 : RPC_STATUS status = ::RpcServerListen(
429 : 1, // Minimum number of handler threads.
430 : RPC_C_LISTEN_MAX_CALLS_DEFAULT,
431 E : TRUE);
432 :
433 E : if (status != RPC_S_OK) {
434 i : LOG(ERROR) << "Failed to run RPC server: " << com::LogWe(status) << ".";
435 i : ignore_result(FinishRpc());
436 i : return false;
437 : }
438 :
439 : // Invoke the callback for the logger started event, giving it a chance to
440 : // abort the startup.
441 E : if (!OnStarted()) {
442 i : ignore_result(StopRpc());
443 i : ignore_result(FinishRpc());
444 i : return false;
445 : }
446 :
447 E : return true;
448 E : }
449 :
450 E : bool Logger::StopRpc() {
451 : // This method may be called by any thread, but it does not inspect or modify
452 : // the internal state of the Logger; so, no synchronization is required.
453 E : VLOG(1) << "Requesting an asynchronous shutdown of the logging service.";
454 :
455 E : RPC_STATUS status = ::RpcMgmtStopServerListening(NULL);
456 E : if (status != RPC_S_OK) {
457 i : LOG(ERROR) << "Failed to stop the RPC server: "
458 : << com::LogWe(status) << ".";
459 i : return false;
460 : }
461 :
462 E : if (!OnInterrupted())
463 i : return false;
464 :
465 E : return true;
466 E : }
467 :
468 E : bool Logger::FinishRpc() {
469 E : bool error = false;
470 E : RPC_STATUS status = RPC_S_OK;
471 :
472 : // Run the RPC server to completion. This is a blocking call which will only
473 : // terminate after someone calls StopRpc() on another thread.
474 E : status = RpcMgmtWaitServerListen();
475 E : if (status != RPC_S_OK) {
476 i : LOG(ERROR) << "Failed to wait for RPC server shutdown: "
477 : << com::LogWe(status) << ".";
478 i : error = true;
479 : }
480 :
481 : status = ::RpcServerUnregisterIf(
482 E : LoggerService_Logger_v1_0_s_ifspec, NULL, FALSE);
483 E : if (status != RPC_S_OK) {
484 i : LOG(ERROR) << "Failed to unregister the Logger RPC interface: "
485 : << com::LogWe(status) << ".";
486 i : error = true;
487 : }
488 :
489 : status = ::RpcServerUnregisterIf(
490 E : LoggerService_LoggerControl_v1_0_s_ifspec, NULL, FALSE);
491 E : if (status != RPC_S_OK) {
492 i : LOG(ERROR) << "Failed to unregister Logger Control RPC interface: "
493 : << com::LogWe(status) << ".";
494 i : error = true;
495 : }
496 :
497 E : LOG(INFO) << "The logging service has stopped.";
498 E : if (!OnStopped())
499 i : error = true;
500 :
501 E : return !error;
502 E : }
503 :
504 : } // namespace logger
505 : } // namespace trace
|