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