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 : : owning_thread_id_(base::PlatformThread::CurrentId()),
129 : destination_(NULL),
130 E : state_(kStopped) {
131 E : }
132 :
133 E : Logger::~Logger() {
134 E : DCHECK_EQ(owning_thread_id_, base::PlatformThread::CurrentId());
135 E : if (state_ != kStopped) {
136 i : ignore_result(Stop());
137 i : ignore_result(RunToCompletion());
138 : }
139 E : DCHECK_EQ(kStopped, state_);
140 E : }
141 :
142 E : bool Logger::Start() {
143 E : DCHECK_EQ(owning_thread_id_, base::PlatformThread::CurrentId());
144 E : DCHECK_EQ(kStopped, state_);
145 :
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 Logger::Stop() {
158 E : if (!StopRpc())
159 i : return false;
160 :
161 E : return true;
162 E : }
163 :
164 E : bool Logger::RunToCompletion() {
165 E : DCHECK_EQ(owning_thread_id_, base::PlatformThread::CurrentId());
166 E : DCHECK_EQ(kRunning, state_);
167 :
168 : // Finish processing all RPC events. If Stop() has previously been called
169 : // this will simply ensure that all outstanding requests are handled. If
170 : // Stop has not been called, this will continue (i.e., block) handling events
171 : // until someone else calls Stop() in another thread.
172 E : if (!FinishRpc())
173 i : return false;
174 :
175 E : DCHECK_EQ(kStopped, state_);
176 :
177 E : return true;
178 E : }
179 :
180 : bool Logger::AppendTrace(HANDLE process,
181 : const DWORD* trace_data,
182 : size_t trace_length,
183 E : std::string* message) {
184 E : DCHECK(trace_data != NULL);
185 E : DCHECK(message != NULL);
186 :
187 : // TODO(rogerm): Add an RPC session to the logger and its interface. This
188 : // would serialize calls per process and provide a convenient mechanism
189 : // for ensuring SymInitialize/Cleanup are called exactly once per client
190 : // process.
191 :
192 E : base::AutoLock auto_lock(symbol_lock_);
193 :
194 : // Initializes the symbols for the process:
195 : // - Defer symbol load until they're needed
196 : // - Use undecorated names
197 : // - Get line numbers
198 E : ::SymSetOptions(SYMOPT_DEFERRED_LOADS | SYMOPT_UNDNAME | SYMOPT_LOAD_LINES);
199 E : if (!::SymInitialize(process, NULL, TRUE)) {
200 i : DWORD error = ::GetLastError();
201 i : LOG(ERROR) << "SymInitialize failed: " << com::LogWe(error) << ".";
202 i : return false;
203 : }
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 Logger::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 E : base::AutoLock auto_lock(symbol_lock_);
248 :
249 : // Initializes the symbols for the process:
250 : // - Defer symbol load until they're needed
251 : // - Use undecorated names
252 : // - Get line numbers
253 E : ::SymSetOptions(SYMOPT_DEFERRED_LOADS | SYMOPT_UNDNAME | SYMOPT_LOAD_LINES);
254 E : if (!::SymInitialize(process, NULL, TRUE)) {
255 i : DWORD error = ::GetLastError();
256 i : LOG(ERROR) << "SymInitialize failed: " << com::LogWe(error) << ".";
257 i : return false;
258 : }
259 :
260 : // Initialize a stack frame structure.
261 : STACKFRAME64 stack_frame;
262 E : ::memset(&stack_frame, 0, sizeof(stack_frame));
263 : #if defined(_WIN64)
264 : int machine_type = IMAGE_FILE_MACHINE_AMD64;
265 : stack_frame.AddrPC.Offset = context->Rip;
266 : stack_frame.AddrFrame.Offset = context->Rbp;
267 : stack_frame.AddrStack.Offset = context->Rsp;
268 : #else
269 E : int machine_type = IMAGE_FILE_MACHINE_I386;
270 E : stack_frame.AddrPC.Offset = context->Eip;
271 E : stack_frame.AddrFrame.Offset = context->Ebp;
272 E : stack_frame.AddrStack.Offset = context->Esp;
273 : #endif
274 E : stack_frame.AddrPC.Mode = AddrModeFlat;
275 E : stack_frame.AddrFrame.Mode = AddrModeFlat;
276 E : stack_frame.AddrStack.Mode = AddrModeFlat;
277 :
278 : // Walk the stack.
279 : while (::StackWalk64(machine_type,
280 : process,
281 : NULL,
282 : &stack_frame,
283 : context,
284 : &ReadProcessMemoryProc64,
285 : &::SymFunctionTableAccess64,
286 : &::SymGetModuleBase64,
287 E : NULL)) {
288 E : trace_data->push_back(stack_frame.AddrPC.Offset);
289 E : }
290 :
291 E : if (!::SymCleanup(process)) {
292 i : DWORD error = ::GetLastError();
293 i : LOG(ERROR) << "SymCleanup failed: " << com::LogWe(error) << ".";
294 i : return false;
295 : }
296 :
297 : // And we're done.
298 E : return true;
299 E : }
300 :
301 E : bool Logger::Write(const base::StringPiece& message) {
302 E : if (message.empty())
303 i : return true;
304 :
305 E : base::AutoLock auto_lock(write_lock_);
306 :
307 : size_t chars_written = ::fwrite(message.data(),
308 : sizeof(std::string::value_type),
309 : message.size(),
310 E : destination_);
311 :
312 E : if (chars_written != message.size()) {
313 i : LOG(ERROR) << "Failed to write log message.";
314 i : return false;
315 : }
316 :
317 : if (message[message.size() - 1] != '\n' &&
318 E : ::fwrite("\n", 1, 1, destination_) != 1) {
319 i : LOG(ERROR) << "Failed to append trailing newline.";
320 i : return false;
321 : }
322 :
323 E : ::fflush(destination_);
324 :
325 E : return true;
326 E : }
327 :
328 E : bool Logger::InitRpc() {
329 : // This method must be called by the owning thread, so no need to otherwise
330 : // synchronize the method invocation.
331 E : DCHECK_EQ(owning_thread_id_, base::PlatformThread::CurrentId());
332 E : DCHECK_EQ(kStopped, state_);
333 :
334 E : RPC_STATUS status = RPC_S_OK;
335 :
336 : // Initialize the RPC protocol we want to use.
337 E : std::wstring protocol(kLoggerRpcProtocol);
338 : std::wstring endpoint(
339 E : GetInstanceString(kLoggerRpcEndpointRoot, instance_id_));
340 :
341 E : VLOG(1) << "Initializing RPC endpoint '" << endpoint << "' "
342 : << "using the '" << protocol << "' protocol.";
343 : status = ::RpcServerUseProtseqEp(
344 : reinterpret_cast<RPC_WSTR>(&protocol[0]),
345 : RPC_C_LISTEN_MAX_CALLS_DEFAULT,
346 : reinterpret_cast<RPC_WSTR>(&endpoint[0]),
347 E : NULL /* Security descriptor. */);
348 E : if (status != RPC_S_OK && status != RPC_S_DUPLICATE_ENDPOINT) {
349 i : LOG(ERROR) << "Failed to init RPC protocol: " << com::LogWe(status) << ".";
350 i : return false;
351 : }
352 :
353 : // Register the logger interface.
354 E : VLOG(1) << "Registering the Logger interface.";
355 : status = ::RpcServerRegisterIf(
356 E : LoggerService_Logger_v1_0_s_ifspec, NULL, NULL);
357 E : if (status != RPC_S_OK) {
358 i : LOG(ERROR) << "Failed to register RPC interface: "
359 : << com::LogWe(status) << ".";
360 i : return false;
361 : }
362 :
363 : // Register the logger control interface.
364 E : VLOG(1) << "Registering the Logger Control interface.";
365 : status = ::RpcServerRegisterIf(
366 E : LoggerService_LoggerControl_v1_0_s_ifspec, NULL, NULL);
367 E : if (status != RPC_S_OK) {
368 i : LOG(ERROR) << "Failed to register RPC interface: "
369 : << com::LogWe(status) << ".";
370 i : return false;
371 : }
372 :
373 E : state_ = kInitialized;
374 :
375 E : return true;
376 E : }
377 :
378 E : bool Logger::StartRPC() {
379 : // This method must be called by the owning thread, so no need to otherwise
380 : // synchronize the method invocation.
381 E : VLOG(1) << "Starting the RPC server.";
382 :
383 E : DCHECK_EQ(owning_thread_id_, base::PlatformThread::CurrentId());
384 E : DCHECK_EQ(kInitialized, state_);
385 :
386 : RPC_STATUS status = ::RpcServerListen(
387 : 1, // Minimum number of handler threads.
388 : RPC_C_LISTEN_MAX_CALLS_DEFAULT,
389 E : TRUE);
390 :
391 E : if (status != RPC_S_OK) {
392 i : LOG(ERROR) << "Failed to run RPC server: " << com::LogWe(status) << ".";
393 i : ignore_result(FinishRpc());
394 i : return false;
395 : }
396 :
397 E : state_ = kRunning;
398 :
399 : // Invoke the callback for the logger started event, giving it a chance to
400 : // abort the startup.
401 : if (!logger_started_callback_.is_null() &&
402 E : !logger_started_callback_.Run(this)) {
403 i : ignore_result(StopRpc());
404 i : ignore_result(FinishRpc());
405 i : return false;
406 : }
407 :
408 E : return true;
409 E : }
410 :
411 E : bool Logger::StopRpc() {
412 : // This method may be called by any thread, but it does not inspect or modify
413 : // the internal state of the Logger; so, no synchronization is required.
414 E : VLOG(1) << "Requesting an asynchronous shutdown of the logging service.";
415 :
416 E : RPC_STATUS status = ::RpcMgmtStopServerListening(NULL);
417 E : if (status != RPC_S_OK) {
418 i : LOG(ERROR) << "Failed to stop the RPC server: "
419 : << com::LogWe(status) << ".";
420 i : return false;
421 : }
422 :
423 E : return true;
424 E : }
425 :
426 E : bool Logger::FinishRpc() {
427 : // This method must be called by the owning thread, so no need to otherwise
428 : // synchronize the method invocation.
429 E : DCHECK_EQ(owning_thread_id_, base::PlatformThread::CurrentId());
430 E : DCHECK(state_ == kRunning || state_ == kInitialized);
431 :
432 E : bool error = false;
433 E : RPC_STATUS status = RPC_S_OK;
434 :
435 : // Run the RPC server to completion. This is a blocking call which will only
436 : // terminate after someone calls StopRpc() on another thread.
437 E : if (state_ == kRunning) {
438 E : state_ = kStopping;
439 E : status = RpcMgmtWaitServerListen();
440 E : if (status != RPC_S_OK) {
441 i : LOG(ERROR) << "Failed to wait for RPC server shutdown: "
442 : << com::LogWe(status) << ".";
443 i : error = true;
444 : }
445 : }
446 :
447 : status = ::RpcServerUnregisterIf(
448 E : LoggerService_Logger_v1_0_s_ifspec, NULL, FALSE);
449 E : if (status != RPC_S_OK) {
450 i : LOG(ERROR) << "Failed to unregister the Logger RPC interface: "
451 : << com::LogWe(status) << ".";
452 i : error = true;
453 : }
454 :
455 : status = ::RpcServerUnregisterIf(
456 E : LoggerService_LoggerControl_v1_0_s_ifspec, NULL, FALSE);
457 E : if (status != RPC_S_OK) {
458 i : LOG(ERROR) << "Failed to unregister Logger Control RPC interface: "
459 : << com::LogWe(status) << ".";
460 i : error = true;
461 : }
462 :
463 E : state_ = kStopped;
464 :
465 E : LOG(INFO) << "The logging service has stopped.";
466 :
467 : if (!logger_stopped_callback_.is_null() &&
468 E : !logger_stopped_callback_.Run(this)) {
469 i : error = true;
470 : }
471 :
472 E : return !error;
473 E : }
474 :
475 : } // namespace logger
476 : } // namespace trace
|