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 : #include "syzygy/trace/logger/logger.h"
16 :
17 : #include "base/bind.h"
18 : #include "base/callback.h"
19 : #include "base/file_util.h"
20 : #include "base/stringprintf.h"
21 : #include "base/files/file_path.h"
22 : #include "base/files/scoped_temp_dir.h"
23 : #include "base/threading/thread.h"
24 : #include "gmock/gmock.h"
25 : #include "gtest/gtest.h"
26 : #include "syzygy/trace/logger/logger_rpc_impl.h"
27 : #include "syzygy/trace/rpc/rpc_helpers.h"
28 :
29 : namespace trace {
30 : namespace logger {
31 :
32 : namespace {
33 :
34 : using testing::_;
35 : using testing::Return;
36 : using trace::client::CreateRpcBinding;
37 : using trace::client::InvokeRpc;
38 : using trace::common::Service;
39 :
40 E : int __declspec(noinline) FunctionA(const base::Callback<void(void)>& callback) {
41 E : callback.Run();
42 E : return 1;
43 E : }
44 :
45 E : int __declspec(noinline) FunctionB(const base::Callback<void(void)>& callback) {
46 E : return FunctionA(callback) + 1;
47 E : }
48 :
49 E : int __declspec(noinline) FunctionC(const base::Callback<void(void)>& callback) {
50 E : return FunctionB(callback) + 1;
51 E : }
52 :
53 : void __declspec(noinline) ExecuteCallbackWithKnownStack(
54 E : const base::Callback<void(void)>& callback) {
55 E : int value = FunctionC(callback);
56 E : ASSERT_EQ(3, value);
57 E : }
58 :
59 E : bool TextContainsKnownStack(const std::string& text, size_t start_offset) {
60 E : size_t function_a = text.find("FunctionA", start_offset);
61 E : if (function_a == std::string::npos)
62 i : return false;
63 :
64 E : size_t function_b = text.find("FunctionB", function_a);
65 E : if (function_b == std::string::npos)
66 i : return false;
67 :
68 E : size_t function_c = text.find("FunctionC", function_b);
69 E : if (function_c == std::string::npos)
70 i : return false;
71 :
72 E : return true;
73 E : }
74 :
75 : class TestLogger : public Logger {
76 : public:
77 : using Logger::destination_;
78 : };
79 :
80 : class LoggerTest : public testing::Test {
81 : public:
82 E : MOCK_METHOD1(LoggerStartedCallback, bool(Service*));
83 E : MOCK_METHOD1(LoggerInterruptedCallback, bool(Service*));
84 E : MOCK_METHOD1(LoggerStoppedCallback, bool(Service*));
85 :
86 E : LoggerTest()
87 : : io_thread_("LoggerTest IO Thread"), instance_manager_(&logger_) {
88 E : }
89 :
90 E : virtual void SetUp() OVERRIDE {
91 E : ASSERT_NO_FATAL_FAILURE(testing::Test::SetUp());
92 :
93 : // Create a log file.
94 E : ASSERT_TRUE(temp_dir_.CreateUniqueTempDir());
95 E : log_file_path_ = temp_dir_.path().AppendASCII("log.txt");
96 E : ASSERT_TRUE(!log_file_path_.empty());
97 E : log_file_.reset(file_util::OpenFile(log_file_path_, "wb"));
98 E : ASSERT_TRUE(log_file_.get() != NULL);
99 :
100 : // Setup the instance ID.
101 E : instance_id_ = base::StringPrintf(L"%d", ::GetCurrentProcessId());
102 :
103 : // Start the IO thread.
104 E : ASSERT_TRUE(io_thread_.StartWithOptions(
105 : base::Thread::Options(MessageLoop::TYPE_IO, 0)));
106 :
107 : // Setup a logger to use.
108 E : logger_.set_instance_id(instance_id_);
109 E : logger_.set_minidump_dir(temp_dir_.path());
110 E : logger_.set_destination(log_file_.get());
111 : logger_.set_started_callback(base::Bind(
112 E : &LoggerTest::LoggerStartedCallback, base::Unretained(this)));
113 : logger_.set_interrupted_callback(base::Bind(
114 E : &LoggerTest::LoggerInterruptedCallback, base::Unretained(this)));
115 : logger_.set_stopped_callback(base::Bind(
116 E : &LoggerTest::LoggerStoppedCallback, base::Unretained(this)));
117 :
118 : // Validate that the Logger's constructor and setters have done their jobs.
119 E : ASSERT_EQ(log_file_.get(), logger_.destination_);
120 E : ASSERT_EQ(temp_dir_.path(), logger_.minidump_dir());
121 E : ASSERT_TRUE(!logger_.instance_id().empty());
122 E : ASSERT_TRUE(!logger_.started_callback().is_null());
123 E : ASSERT_TRUE(!logger_.interrupted_callback().is_null());
124 E : ASSERT_TRUE(!logger_.stopped_callback().is_null());
125 E : ASSERT_EQ(Logger::kUnused, logger_.state());
126 :
127 : // Start the logger.
128 : EXPECT_CALL(*this, LoggerStartedCallback(&logger_))
129 E : .WillOnce(Return(true));
130 E : ASSERT_TRUE(logger_.Start());
131 E : ASSERT_EQ(Logger::kRunning, logger_.state());
132 :
133 : // At some point we expect someone to stop the logger, and the logger
134 : // interrupted callback will fire.
135 : EXPECT_CALL(*this, LoggerInterruptedCallback(&logger_))
136 E : .WillOnce(Return(true));
137 E : }
138 :
139 E : virtual void TearDown() OVERRIDE {
140 E : if (logger_.state() != Logger::kStopped) {
141 E : ASSERT_TRUE(logger_.Stop());
142 E : ASSERT_NO_FATAL_FAILURE(WaitForLoggerToFinish());
143 : }
144 E : }
145 :
146 E : void WaitForLoggerToFinish() {
147 : EXPECT_CALL(*this, LoggerStoppedCallback(&logger_))
148 E : .WillOnce(Return(true));
149 E : ASSERT_TRUE(logger_.Join());
150 E : ASSERT_EQ(Logger::kStopped, logger_.state());
151 E : }
152 :
153 E : void DoCaptureRemoteTrace(HANDLE process, std::vector<DWORD>* trace_data) {
154 E : CONTEXT context = {};
155 E : ::RtlCaptureContext(&context);
156 E : ASSERT_TRUE(logger_.CaptureRemoteTrace(process, &context, trace_data));
157 E : }
158 :
159 : static const char kLine1[];
160 : static const char kLine2[];
161 : static const char kLine3[];
162 :
163 : base::ScopedTempDir temp_dir_;
164 : base::FilePath log_file_path_;
165 : file_util::ScopedFILE log_file_;
166 : std::wstring instance_id_;
167 : base::Thread io_thread_;
168 : TestLogger logger_;
169 : RpcLoggerInstanceManager instance_manager_;
170 : };
171 :
172 E : void DoRpcWriteWithContext(handle_t rpc_binding, const unsigned char* message) {
173 E : CONTEXT rtl_context = {};
174 E : ::RtlCaptureContext(&rtl_context);
175 :
176 E : ExecutionContext exc_context = {};
177 E : exc_context.edi = rtl_context.Edi;
178 E : exc_context.esi = rtl_context.Esi;
179 E : exc_context.ebx = rtl_context.Ebx;
180 E : exc_context.edx = rtl_context.Edx;
181 E : exc_context.ecx = rtl_context.Ecx;
182 E : exc_context.eax = rtl_context.Eax;
183 E : exc_context.ebp = rtl_context.Ebp;
184 E : exc_context.eip = rtl_context.Eip;
185 E : exc_context.seg_cs = rtl_context.SegCs;
186 E : exc_context.eflags = rtl_context.EFlags;
187 E : exc_context.esp = rtl_context.Esp;
188 E : exc_context.seg_ss = rtl_context.SegSs;
189 :
190 : ASSERT_TRUE(
191 E : LoggerClient_WriteWithContext(rpc_binding, message, &exc_context));
192 E : }
193 :
194 : const char LoggerTest::kLine1[] = "This is line 1\n";
195 : const char LoggerTest::kLine2[] = "This is line 2"; // Note no trailing '\n'.
196 : const char LoggerTest::kLine3[] = "This is line 3\n";
197 :
198 E : inline const unsigned char* MakeUnsigned(const char* s) {
199 E : return reinterpret_cast<const unsigned char*>(s);
200 E : }
201 :
202 E : void DoRpcCreateMiniDump(handle_t rpc_binding) {
203 E : CONTEXT ctx = {};
204 E : ::RtlCaptureContext(&ctx);
205 E : EXCEPTION_RECORD exc_rec = {};
206 E : exc_rec.ExceptionAddress = reinterpret_cast<void*>(ctx.Eip);
207 E : exc_rec.ExceptionCode = EXCEPTION_ARRAY_BOUNDS_EXCEEDED;
208 E : EXCEPTION_POINTERS exc_ptrs = { &exc_rec, &ctx };
209 : ASSERT_TRUE(
210 : LoggerClient_SaveMiniDump(rpc_binding,
211 : ::GetCurrentThreadId(),
212 : reinterpret_cast<unsigned long>(&exc_ptrs),
213 E : 0));
214 E : }
215 :
216 : } // namespace
217 :
218 E : TEST_F(LoggerTest, StackTraceHandling) {
219 E : HANDLE process = ::GetCurrentProcess();
220 E : std::vector<DWORD> trace_data;
221 : ASSERT_NO_FATAL_FAILURE(ExecuteCallbackWithKnownStack(base::Bind(
222 : &LoggerTest::DoCaptureRemoteTrace,
223 : base::Unretained(this),
224 : process,
225 E : &trace_data)));
226 :
227 : // Validate the returned textual stack trace.
228 E : std::string text;
229 : ASSERT_TRUE(logger_.AppendTrace(
230 E : process, trace_data.data(), trace_data.size(), &text));
231 E : size_t function_a = text.find("FunctionA", 0);
232 E : ASSERT_TRUE(function_a != std::string::npos);
233 E : size_t function_b = text.find("FunctionB", function_a);
234 E : ASSERT_TRUE(function_b != std::string::npos);
235 E : size_t function_c = text.find("FunctionC", function_b);
236 E : ASSERT_TRUE(function_c != std::string::npos);
237 E : }
238 :
239 E : TEST_F(LoggerTest, Write) {
240 : // Write the lines.
241 E : ASSERT_TRUE(logger_.Write(kLine1));
242 E : ASSERT_TRUE(logger_.Write(kLine2));
243 E : ASSERT_TRUE(logger_.Write(kLine3));
244 :
245 : // Stop the logger.
246 E : ASSERT_TRUE(logger_.Stop());
247 E : ASSERT_NO_FATAL_FAILURE(WaitForLoggerToFinish());
248 :
249 : // Close the log file.
250 E : log_file_.reset(NULL);
251 :
252 : // Read in the log contents.
253 E : std::string contents;
254 E : ASSERT_TRUE(file_util::ReadFileToString(log_file_path_, &contents));
255 :
256 : // Build the expected contents (append a newline to line2)
257 E : std::string expected_contents(kLine1);
258 E : expected_contents += kLine2;
259 E : expected_contents += '\n';
260 E : expected_contents += kLine3;
261 :
262 : // Compare the log contents.
263 E : EXPECT_EQ(expected_contents, contents);
264 E : }
265 :
266 E : TEST_F(LoggerTest, RpcWrite) {
267 : // Connect to the logger over RPC.
268 E : trace::client::ScopedRpcBinding rpc_binding;
269 : std::wstring endpoint(
270 E : trace::client::GetInstanceString(kLoggerRpcEndpointRoot, instance_id_));
271 E : ASSERT_TRUE(rpc_binding.Open(kLoggerRpcProtocol, endpoint));
272 :
273 : // Write to and stop the logger via RPC.
274 E : ASSERT_TRUE(LoggerClient_Write(rpc_binding.Get(), MakeUnsigned(kLine1)));
275 E : ASSERT_TRUE(LoggerClient_Write(rpc_binding.Get(), MakeUnsigned(kLine2)));
276 E : ASSERT_TRUE(LoggerClient_Write(rpc_binding.Get(), MakeUnsigned(kLine3)));
277 E : ASSERT_TRUE(LoggerClient_Stop(rpc_binding.Get()));
278 E : ASSERT_TRUE(rpc_binding.Close());
279 :
280 : // Wait for the logger to finish shutting down.
281 E : EXPECT_NO_FATAL_FAILURE(WaitForLoggerToFinish());
282 :
283 : // Close the log file.
284 E : log_file_.reset(NULL);
285 :
286 : // Read in the log contents.
287 E : std::string contents;
288 E : ASSERT_TRUE(file_util::ReadFileToString(log_file_path_, &contents));
289 :
290 : // Build the expected contents (append a newline to line2)
291 E : std::string expected_contents(kLine1);
292 E : expected_contents += kLine2;
293 E : expected_contents += '\n';
294 E : expected_contents += kLine3;
295 :
296 : // Compare the log contents.
297 E : EXPECT_EQ(expected_contents, contents);
298 E : }
299 :
300 E : TEST_F(LoggerTest, RpcWriteWithStack) {
301 : // Connect to the logger over RPC.
302 E : trace::client::ScopedRpcBinding rpc_binding;
303 : std::wstring endpoint(
304 E : trace::client::GetInstanceString(kLoggerRpcEndpointRoot, instance_id_));
305 E : ASSERT_TRUE(rpc_binding.Open(kLoggerRpcProtocol, endpoint));
306 :
307 E : HANDLE process = ::GetCurrentProcess();
308 E : std::vector<DWORD> trace_data;
309 : ASSERT_NO_FATAL_FAILURE(ExecuteCallbackWithKnownStack(base::Bind(
310 : &LoggerTest::DoCaptureRemoteTrace,
311 : base::Unretained(this),
312 : process,
313 E : &trace_data)));
314 :
315 : // Write to and stop the logger via RPC.
316 : ASSERT_TRUE(LoggerClient_WriteWithTrace(rpc_binding.Get(),
317 : MakeUnsigned(kLine1),
318 : trace_data.data(),
319 E : trace_data.size()));
320 E : ASSERT_TRUE(LoggerClient_Stop(rpc_binding.Get()));
321 E : ASSERT_TRUE(rpc_binding.Close());
322 :
323 : // Wait for the logger to finish shutting down.
324 E : EXPECT_NO_FATAL_FAILURE(WaitForLoggerToFinish());
325 :
326 : // Close the log file.
327 E : log_file_.reset(NULL);
328 :
329 : // Read in the log contents.
330 E : std::string text;
331 E : ASSERT_TRUE(file_util::ReadFileToString(log_file_path_, &text));
332 :
333 : // Validate that we see the expected function chain.
334 E : size_t line_1 = text.find(kLine1, 0);
335 E : ASSERT_TRUE(line_1 != std::string::npos);
336 E : ASSERT_TRUE(TextContainsKnownStack(text, line_1));
337 E : }
338 :
339 E : TEST_F(LoggerTest, RpcWriteWithContext) {
340 : // Connect to the logger over RPC.
341 E : trace::client::ScopedRpcBinding rpc_binding;
342 : std::wstring endpoint(
343 E : trace::client::GetInstanceString(kLoggerRpcEndpointRoot, instance_id_));
344 E : ASSERT_TRUE(rpc_binding.Open(kLoggerRpcProtocol, endpoint));
345 :
346 : // Write to and stop the logger via RPC.
347 : ASSERT_NO_FATAL_FAILURE(ExecuteCallbackWithKnownStack(base::Bind(
348 : &DoRpcWriteWithContext,
349 : rpc_binding.Get(),
350 E : MakeUnsigned(kLine2))));
351 E : ASSERT_TRUE(LoggerClient_Stop(rpc_binding.Get()));
352 E : ASSERT_TRUE(rpc_binding.Close());
353 :
354 : // Wait for the logger to finish shutting down.
355 E : EXPECT_NO_FATAL_FAILURE(WaitForLoggerToFinish());
356 :
357 : // Close the log file.
358 E : log_file_.reset(NULL);
359 :
360 : // Read in the log contents.
361 E : std::string text;
362 E : ASSERT_TRUE(file_util::ReadFileToString(log_file_path_, &text));
363 :
364 : // Validate that we see the expected function chain.
365 E : size_t line_2 = text.find(kLine2, 0);
366 E : ASSERT_TRUE(line_2 != std::string::npos);
367 E : ASSERT_TRUE(TextContainsKnownStack(text, line_2));
368 E : }
369 :
370 E : TEST_F(LoggerTest, RpcGenerateMiniDump) {
371 : // Connect to the logger over RPC.
372 E : trace::client::ScopedRpcBinding rpc_binding;
373 : std::wstring endpoint(
374 E : trace::client::GetInstanceString(kLoggerRpcEndpointRoot, instance_id_));
375 E : ASSERT_TRUE(rpc_binding.Open(kLoggerRpcProtocol, endpoint));
376 :
377 : // Write to and stop the logger via RPC.
378 : ASSERT_NO_FATAL_FAILURE(ExecuteCallbackWithKnownStack(base::Bind(
379 : &DoRpcCreateMiniDump,
380 E : rpc_binding.Get())));
381 E : ASSERT_TRUE(LoggerClient_Stop(rpc_binding.Get()));
382 E : ASSERT_TRUE(rpc_binding.Close());
383 :
384 : // Wait for the logger to finish shutting down.
385 E : EXPECT_NO_FATAL_FAILURE(WaitForLoggerToFinish());
386 :
387 : // We should have exactly one mini-dump in the temp directory.
388 : using file_util::FileEnumerator;
389 E : FileEnumerator fe(temp_dir_.path(), false, FileEnumerator::FILES, L"*.dmp");
390 E : base::FilePath mini_dump(fe.Next());
391 E : EXPECT_FALSE(mini_dump.empty());
392 E : EXPECT_TRUE(fe.Next().empty());
393 :
394 : // TODO(rogerm): Validate the stack-trace in the mini-dump.
395 E : }
396 :
397 : } // namespace logger
398 : } // namespace trace
|