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