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