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