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_path.h"
20 : #include "base/file_util.h"
21 : #include "base/scoped_temp_dir.h"
22 : #include "base/stringprintf.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 :
39 E : int __declspec(noinline) FunctionA(const base::Callback<void(void)>& callback) {
40 E : callback.Run();
41 E : return 1;
42 E : }
43 :
44 E : int __declspec(noinline) FunctionB(const base::Callback<void(void)>& callback) {
45 E : return FunctionA(callback) + 1;
46 E : }
47 :
48 E : int __declspec(noinline) FunctionC(const base::Callback<void(void)>& callback) {
49 E : return FunctionB(callback) + 1;
50 E : }
51 :
52 : void __declspec(noinline) ExecuteCallbackWithKnownStack(
53 E : const base::Callback<void(void)>& callback) {
54 E : int value = FunctionC(callback);
55 E : ASSERT_EQ(3, value);
56 E : }
57 :
58 E : bool TextContainsKnownStack(const std::string& text, size_t start_offset) {
59 E : size_t function_a = text.find("FunctionA", start_offset);
60 E : if (function_a == std::string::npos)
61 i : return false;
62 :
63 E : size_t function_b = text.find("FunctionB", function_a);
64 E : if (function_b == std::string::npos)
65 i : return false;
66 :
67 E : size_t function_c = text.find("FunctionC", function_b);
68 E : if (function_c == std::string::npos)
69 i : return false;
70 :
71 E : return true;
72 E : }
73 :
74 : class TestLogger : public Logger {
75 : public:
76 : using Logger::owning_thread_id_;
77 : using Logger::destination_;
78 : using Logger::state_;
79 : using Logger::instance_id_;
80 : using Logger::logger_started_callback_;
81 : using Logger::logger_stopped_callback_;
82 : };
83 :
84 : class LoggerTest : public testing::Test {
85 : public:
86 E : MOCK_METHOD1(LoggerStartedCallback, bool(Logger*));
87 E : MOCK_METHOD1(LoggerStoppedCallback, bool(Logger*));
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(file_util::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(MessageLoop::TYPE_IO, 0)));
109 :
110 : // Setup a logger to use.
111 E : logger_.set_instance_id(instance_id_);
112 E : logger_.set_destination(log_file_.get());
113 : logger_.set_logger_started_callback(
114 E : base::Bind(&LoggerTest::LoggerStartedCallback, base::Unretained(this)));
115 : logger_.set_logger_stopped_callback(
116 E : base::Bind(&LoggerTest::LoggerStoppedCallback, base::Unretained(this)));
117 :
118 : // Validate that the Logger's constructor and setters have done their jobs.
119 E : ASSERT_EQ(base::PlatformThread::CurrentId(), logger_.owning_thread_id_);
120 E : ASSERT_EQ(log_file_.get(), logger_.destination_);
121 E : ASSERT_TRUE(!logger_.instance_id_.empty());
122 E : ASSERT_TRUE(!logger_.logger_started_callback_.is_null());
123 E : ASSERT_TRUE(!logger_.logger_stopped_callback_.is_null());
124 E : ASSERT_EQ(Logger::kStopped, logger_.state_);
125 :
126 : // Start the logger.
127 : EXPECT_CALL(*this, LoggerStartedCallback(&logger_))
128 E : .WillOnce(Return(true));
129 E : ASSERT_TRUE(logger_.Start());
130 E : ASSERT_EQ(Logger::kRunning, logger_.state_);
131 E : }
132 :
133 E : virtual void TearDown() OVERRIDE {
134 E : if (logger_.state_ != Logger::kStopped) {
135 E : ASSERT_TRUE(logger_.Stop());
136 E : ASSERT_NO_FATAL_FAILURE(WaitForLoggerToFinish());
137 : }
138 E : }
139 :
140 E : void WaitForLoggerToFinish() {
141 : EXPECT_CALL(*this, LoggerStoppedCallback(&logger_))
142 E : .WillOnce(Return(true));
143 E : ASSERT_TRUE(logger_.RunToCompletion());
144 E : ASSERT_EQ(Logger::kStopped, logger_.state_);
145 E : }
146 :
147 E : void DoCaptureRemoteTrace(HANDLE process, std::vector<DWORD>* trace_data) {
148 E : CONTEXT context = {};
149 E : ::RtlCaptureContext(&context);
150 E : ASSERT_TRUE(logger_.CaptureRemoteTrace(process, &context, trace_data));
151 E : }
152 :
153 : static const char kLine1[];
154 : static const char kLine2[];
155 : static const char kLine3[];
156 :
157 : ScopedTempDir temp_dir_;
158 : FilePath log_file_path_;
159 : file_util::ScopedFILE log_file_;
160 : std::wstring instance_id_;
161 : base::Thread io_thread_;
162 : TestLogger logger_;
163 : RpcLoggerInstanceManager instance_manager_;
164 : };
165 :
166 E : void DoRpcWriteWithContext(handle_t rpc_binding, const unsigned char* message) {
167 E : CONTEXT rtl_context = {};
168 E : ::RtlCaptureContext(&rtl_context);
169 :
170 E : ExecutionContext exc_context = {};
171 E : exc_context.edi = rtl_context.Edi;
172 E : exc_context.esi = rtl_context.Esi;
173 E : exc_context.ebx = rtl_context.Ebx;
174 E : exc_context.edx = rtl_context.Edx;
175 E : exc_context.ecx = rtl_context.Ecx;
176 E : exc_context.eax = rtl_context.Eax;
177 E : exc_context.ebp = rtl_context.Ebp;
178 E : exc_context.eip = rtl_context.Eip;
179 E : exc_context.seg_cs = rtl_context.SegCs;
180 E : exc_context.eflags = rtl_context.EFlags;
181 E : exc_context.esp = rtl_context.Esp;
182 E : exc_context.seg_ss = rtl_context.SegSs;
183 :
184 : ASSERT_TRUE(
185 E : LoggerClient_WriteWithContext(rpc_binding, message, &exc_context));
186 E : }
187 :
188 : const char LoggerTest::kLine1[] = "This is line 1\n";
189 : const char LoggerTest::kLine2[] = "This is line 2"; // Note no trailing '\n'.
190 : const char LoggerTest::kLine3[] = "This is line 3\n";
191 :
192 E : inline const unsigned char* MakeUnsigned(const char* s) {
193 E : return reinterpret_cast<const unsigned char*>(s);
194 E : }
195 :
196 : } // namespace
197 :
198 E : TEST_F(LoggerTest, StackTraceHandling) {
199 E : HANDLE process = ::GetCurrentProcess();
200 E : std::vector<DWORD> trace_data;
201 : ASSERT_NO_FATAL_FAILURE(ExecuteCallbackWithKnownStack(base::Bind(
202 : &LoggerTest::DoCaptureRemoteTrace,
203 : base::Unretained(this),
204 : process,
205 E : &trace_data)));
206 :
207 : // Validate the returned textual stack trace.
208 E : std::string text;
209 : ASSERT_TRUE(logger_.AppendTrace(
210 E : process, trace_data.data(), trace_data.size(), &text));
211 E : size_t function_a = text.find("FunctionA", 0);
212 E : ASSERT_TRUE(function_a != std::string::npos);
213 E : size_t function_b = text.find("FunctionB", function_a);
214 E : ASSERT_TRUE(function_b != std::string::npos);
215 E : size_t function_c = text.find("FunctionC", function_b);
216 E : ASSERT_TRUE(function_c != std::string::npos);
217 E : }
218 :
219 E : TEST_F(LoggerTest, Write) {
220 : // Write the lines.
221 E : ASSERT_TRUE(logger_.Write(kLine1));
222 E : ASSERT_TRUE(logger_.Write(kLine2));
223 E : ASSERT_TRUE(logger_.Write(kLine3));
224 :
225 : // Stop the logger.
226 E : ASSERT_TRUE(logger_.Stop());
227 E : ASSERT_NO_FATAL_FAILURE(WaitForLoggerToFinish());
228 :
229 : // Close the log file.
230 E : log_file_.reset(NULL);
231 :
232 : // Read in the log contents.
233 E : std::string contents;
234 E : ASSERT_TRUE(file_util::ReadFileToString(log_file_path_, &contents));
235 :
236 : // Build the expected contents (append a newline to line2)
237 E : std::string expected_contents(kLine1);
238 E : expected_contents += kLine2;
239 E : expected_contents += '\n';
240 E : expected_contents += kLine3;
241 :
242 : // Compare the log contents.
243 E : EXPECT_EQ(expected_contents, contents);
244 E : }
245 :
246 E : TEST_F(LoggerTest, RpcWrite) {
247 : // Connect to the logger over RPC.
248 E : trace::client::ScopedRpcBinding rpc_binding;
249 : std::wstring endpoint(
250 E : trace::client::GetInstanceString(kLoggerRpcEndpointRoot, instance_id_));
251 E : ASSERT_TRUE(rpc_binding.Open(kLoggerRpcProtocol, endpoint));
252 :
253 : // Write to and stop the logger via RPC.
254 E : ASSERT_TRUE(LoggerClient_Write(rpc_binding.Get(), MakeUnsigned(kLine1)));
255 E : ASSERT_TRUE(LoggerClient_Write(rpc_binding.Get(), MakeUnsigned(kLine2)));
256 E : ASSERT_TRUE(LoggerClient_Write(rpc_binding.Get(), MakeUnsigned(kLine3)));
257 E : ASSERT_TRUE(LoggerClient_Stop(rpc_binding.Get()));
258 E : ASSERT_TRUE(rpc_binding.Close());
259 :
260 : // Wait for the logger to finish shutting down.
261 E : EXPECT_NO_FATAL_FAILURE(WaitForLoggerToFinish());
262 :
263 : // Close the log file.
264 E : log_file_.reset(NULL);
265 :
266 : // Read in the log contents.
267 E : std::string contents;
268 E : ASSERT_TRUE(file_util::ReadFileToString(log_file_path_, &contents));
269 :
270 : // Build the expected contents (append a newline to line2)
271 E : std::string expected_contents(kLine1);
272 E : expected_contents += kLine2;
273 E : expected_contents += '\n';
274 E : expected_contents += kLine3;
275 :
276 : // Compare the log contents.
277 E : EXPECT_EQ(expected_contents, contents);
278 E : }
279 :
280 E : TEST_F(LoggerTest, RpcWriteWithStack) {
281 : // Connect to the logger over RPC.
282 E : trace::client::ScopedRpcBinding rpc_binding;
283 : std::wstring endpoint(
284 E : trace::client::GetInstanceString(kLoggerRpcEndpointRoot, instance_id_));
285 E : ASSERT_TRUE(rpc_binding.Open(kLoggerRpcProtocol, endpoint));
286 :
287 E : HANDLE process = ::GetCurrentProcess();
288 E : std::vector<DWORD> trace_data;
289 : ASSERT_NO_FATAL_FAILURE(ExecuteCallbackWithKnownStack(base::Bind(
290 : &LoggerTest::DoCaptureRemoteTrace,
291 : base::Unretained(this),
292 : process,
293 E : &trace_data)));
294 :
295 : // Write to and stop the logger via RPC.
296 : ASSERT_TRUE(LoggerClient_WriteWithTrace(rpc_binding.Get(),
297 : MakeUnsigned(kLine1),
298 : trace_data.data(),
299 E : trace_data.size()));
300 E : ASSERT_TRUE(LoggerClient_Stop(rpc_binding.Get()));
301 E : ASSERT_TRUE(rpc_binding.Close());
302 :
303 : // Wait for the logger to finish shutting down.
304 E : EXPECT_NO_FATAL_FAILURE(WaitForLoggerToFinish());
305 :
306 : // Close the log file.
307 E : log_file_.reset(NULL);
308 :
309 : // Read in the log contents.
310 E : std::string text;
311 E : ASSERT_TRUE(file_util::ReadFileToString(log_file_path_, &text));
312 :
313 : // Validate that we see the expected function chain.
314 E : size_t line_1 = text.find(kLine1, 0);
315 E : ASSERT_TRUE(line_1 != std::string::npos);
316 E : ASSERT_TRUE(TextContainsKnownStack(text, line_1));
317 E : }
318 :
319 E : TEST_F(LoggerTest, RpcWriteWithContext) {
320 : // Connect to the logger over RPC.
321 E : trace::client::ScopedRpcBinding rpc_binding;
322 : std::wstring endpoint(
323 E : trace::client::GetInstanceString(kLoggerRpcEndpointRoot, instance_id_));
324 E : ASSERT_TRUE(rpc_binding.Open(kLoggerRpcProtocol, endpoint));
325 :
326 : // Write to and stop the logger via RPC.
327 : ASSERT_NO_FATAL_FAILURE(ExecuteCallbackWithKnownStack(base::Bind(
328 : &DoRpcWriteWithContext,
329 : rpc_binding.Get(),
330 E : MakeUnsigned(kLine2))));
331 E : ASSERT_TRUE(LoggerClient_Stop(rpc_binding.Get()));
332 E : ASSERT_TRUE(rpc_binding.Close());
333 :
334 : // Wait for the logger to finish shutting down.
335 E : EXPECT_NO_FATAL_FAILURE(WaitForLoggerToFinish());
336 :
337 : // Close the log file.
338 E : log_file_.reset(NULL);
339 :
340 : // Read in the log contents.
341 E : std::string text;
342 E : ASSERT_TRUE(file_util::ReadFileToString(log_file_path_, &text));
343 :
344 : // Validate that we see the expected function chain.
345 E : size_t line_2 = text.find(kLine2, 0);
346 E : ASSERT_TRUE(line_2 != std::string::npos);
347 E : ASSERT_TRUE(TextContainsKnownStack(text, line_2));
348 E : }
349 :
350 : } // namespace logger
351 : } // namespace trace
|