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 : // Implementation of RPC call-trace parsing.
16 :
17 : #include "syzygy/trace/parse/parse_engine_rpc.h"
18 :
19 : #include "base/file_util.h"
20 : #include "base/logging.h"
21 : #include "syzygy/common/align.h"
22 : #include "syzygy/common/com_utils.h"
23 : #include "syzygy/trace/parse/parse_utils.h"
24 :
25 : using common::AlignUp;
26 : using common::AlignUp64;
27 :
28 : namespace trace {
29 : namespace parser {
30 :
31 E : ParseEngineRpc::ParseEngineRpc() : ParseEngine("RPC", true) {
32 E : }
33 :
34 E : ParseEngineRpc::~ParseEngineRpc() {
35 E : }
36 :
37 : bool ParseEngineRpc::IsRecognizedTraceFile(
38 E : const base::FilePath& trace_file_path) {
39 E : base::ScopedFILE trace_file(base::OpenFile(trace_file_path, "rb"));
40 E : if (!trace_file.get()) {
41 i : DWORD error = ::GetLastError();
42 i : LOG(ERROR) << "Unable to open '" << trace_file_path.value() << "': "
43 : << ::common::LogWe(error) << ".";
44 i : return false;
45 : }
46 :
47 E : TraceFileHeader::Signature signature = {};
48 : size_t bytes_read = ::fread(&signature,
49 : 1,
50 : sizeof(signature),
51 E : trace_file.get());
52 E : if (bytes_read < sizeof(signature)) {
53 i : LOG(ERROR) << "Failed to read trace file signature.";
54 i : return false;
55 : }
56 :
57 : return 0 == ::memcmp(&signature,
58 : &TraceFileHeader::kSignatureValue,
59 E : sizeof(signature));
60 E : }
61 :
62 E : bool ParseEngineRpc::OpenTraceFile(const base::FilePath& trace_file_path) {
63 E : trace_file_set_.push_back(trace_file_path);
64 E : return true;
65 E : }
66 :
67 E : bool ParseEngineRpc::CloseAllTraceFiles() {
68 E : trace_file_set_.clear();
69 E : return true;
70 E : }
71 :
72 E : bool ParseEngineRpc::ConsumeAllEvents() {
73 E : TraceFileIter it = trace_file_set_.begin();
74 E : for (; it != trace_file_set_.end(); ++it) {
75 E : if (!ConsumeTraceFile(*it)) {
76 i : LOG(ERROR) << "Failed to consume '" << it->value() << "'.";
77 i : return false;
78 : }
79 E : }
80 :
81 E : return true;
82 E : }
83 :
84 E : bool ParseEngineRpc::ConsumeTraceFile(const base::FilePath& trace_file_path) {
85 E : DCHECK(!trace_file_path.empty());
86 :
87 E : LOG(INFO) << "Processing '" << trace_file_path.BaseName().value() << "'.";
88 :
89 E : base::ScopedFILE trace_file(base::OpenFile(trace_file_path, "rb"));
90 E : if (!trace_file.get()) {
91 i : DWORD error = ::GetLastError();
92 i : LOG(ERROR) << "Unable to open '" << trace_file_path.value() << "': "
93 : << ::common::LogWe(error) << ".";
94 i : return false;
95 : }
96 :
97 : // Let's reserve some space for the variable length header.
98 E : const size_t kReasonableHeaderSize = 4096;
99 E : std::vector<uint8> raw_buffer;
100 E : raw_buffer.reserve(kReasonableHeaderSize);
101 E : raw_buffer.resize(sizeof(TraceFileHeader));
102 :
103 : // Populate the buffer.
104 E : DCHECK_EQ(raw_buffer.size(), sizeof(TraceFileHeader));
105 : size_t bytes_read = ::fread(&raw_buffer[0],
106 : 1,
107 : raw_buffer.size(),
108 E : trace_file.get());
109 E : if (bytes_read != raw_buffer.size()) {
110 i : LOG(ERROR) << "Failed to read trace file header.";
111 i : return false;
112 : }
113 :
114 : // Create a typed alias to the raw buffer.
115 : const TraceFileHeader* file_header =
116 E : reinterpret_cast<const TraceFileHeader*>(&raw_buffer[0]);
117 :
118 : // Check the file signature.
119 : if (0 != memcmp(&file_header->signature,
120 : &TraceFileHeader::kSignatureValue,
121 E : sizeof(file_header->signature))) {
122 i : LOG(ERROR) << "Not a valid RPC call-trace file.";
123 i : return false;
124 : }
125 :
126 : // Make sure there's enough room for the variable length part of the header
127 : // and then append read the rest of the header. Note that the underlying raw
128 : // buffer might move when it is resized.
129 E : size_t bytes_to_read = file_header->header_size - raw_buffer.size();
130 E : raw_buffer.resize(file_header->header_size);
131 E : file_header = reinterpret_cast<const TraceFileHeader*>(&raw_buffer[0]);
132 : bytes_read = ::fread(&raw_buffer[sizeof(TraceFileHeader)],
133 : 1,
134 : bytes_to_read,
135 E : trace_file.get());
136 E : if (bytes_read != bytes_to_read) {
137 i : LOG(ERROR) << "Failed to read trace file header.";
138 i : return false;
139 : }
140 :
141 : // Populate the system information which will be fed to the OnProcessStarted
142 : // event.
143 E : TraceSystemInfo system_info = {};
144 E : system_info.os_version_info = file_header->os_version_info;
145 E : system_info.system_info = file_header->system_info;
146 E : system_info.memory_status = file_header->memory_status;
147 E : system_info.clock_info = file_header->clock_info;
148 :
149 : // Parse the header blob. This fails if there is any extra data, enforcing
150 : // a valid header size as a side effect.
151 E : std::wstring module_path;
152 E : std::wstring command_line;
153 : if (!ParseTraceFileHeaderBlob(*file_header, &module_path, &command_line,
154 E : &system_info.environment_strings)) {
155 i : LOG(ERROR) << "Unable to parse trace file header blob.";
156 i : return false;
157 : }
158 :
159 : // Add the executable's module information to the process map. This is in
160 : // case the executable itself is instrumented, so that trace events will map
161 : // to a module in the process map.
162 E : ModuleInformation module_info;
163 E : module_info.base_address.set_value(file_header->module_base_address);
164 E : module_info.path = module_path;
165 E : module_info.module_size = file_header->module_size;
166 E : module_info.module_checksum = file_header->module_checksum;
167 E : module_info.module_time_date_stamp = file_header->module_time_date_stamp;
168 E : AddModuleInformation(file_header->process_id, module_info);
169 :
170 : // Notify the event handler that a process has started.
171 : base::Time start_time(base::Time::FromFileTime(
172 E : file_header->clock_info.file_time));
173 : event_handler_->OnProcessStarted(start_time, file_header->process_id,
174 E : &system_info);
175 :
176 : // Consume the body of the trace file.
177 : uint64 next_segment = AlignUp64(file_header->header_size,
178 E : file_header->block_size);
179 E : scoped_ptr<uint8> buffer;
180 E : size_t buffer_size = 0;
181 E : while (true) {
182 E : if (::_fseeki64(trace_file.get(), next_segment, SEEK_SET) != 0) {
183 i : LOG(ERROR) << "Failed to seek segment boundary " << next_segment << ".";
184 i : return false;
185 : }
186 :
187 : RecordPrefix segment_prefix;
188 : if (::fread(&segment_prefix,
189 : sizeof(segment_prefix),
190 : 1,
191 E : trace_file.get()) != 1) {
192 E : if (::feof(trace_file.get()))
193 E : break;
194 :
195 i : LOG(ERROR) << "Failed to read segment header prefix.";
196 i : return false;
197 : }
198 :
199 : if (segment_prefix.type != TraceFileSegmentHeader::kTypeId ||
200 : segment_prefix.size != sizeof(TraceFileSegmentHeader) ||
201 : segment_prefix.version.hi != TRACE_VERSION_HI ||
202 E : segment_prefix.version.lo != TRACE_VERSION_LO) {
203 i : LOG(ERROR) << "Unrecognized record prefix for segment header.";
204 i : return false;
205 : }
206 :
207 : TraceFileSegmentHeader segment_header;
208 : if (::fread(&segment_header,
209 : sizeof(segment_header),
210 : 1,
211 E : trace_file.get()) != 1) {
212 i : LOG(ERROR) << "Failed to read segment header.";
213 i : return false;
214 : }
215 :
216 : size_t aligned_size = AlignUp(segment_header.segment_length,
217 E : file_header->block_size);
218 :
219 E : if (aligned_size > buffer_size) {
220 E : buffer.reset(reinterpret_cast<uint8*>(::malloc(aligned_size)));
221 E : buffer_size = aligned_size;
222 : }
223 :
224 : if (::fread(buffer.get(), segment_header.segment_length, 1,
225 E : trace_file.get()) != 1) {
226 i : LOG(ERROR) << "Failed to read segment.";
227 i : return false;
228 : }
229 :
230 : if (!ConsumeSegmentEvents(*file_header,
231 : segment_header,
232 : buffer.get(),
233 E : segment_header.segment_length)) {
234 i : return false;
235 : }
236 :
237 : next_segment = AlignUp64(
238 : next_segment + sizeof(segment_prefix) + sizeof(segment_header) +
239 : segment_header.segment_length,
240 E : file_header->block_size);
241 E : }
242 :
243 E : return true;
244 E : }
245 :
246 : bool ParseEngineRpc::ConsumeSegmentEvents(
247 : const TraceFileHeader& file_header,
248 : const TraceFileSegmentHeader& segment_header,
249 : uint8* buffer,
250 E : size_t buffer_length) {
251 E : DCHECK(buffer != NULL);
252 E : DCHECK(event_handler_ != NULL);
253 :
254 E : EVENT_TRACE event_record = {};
255 :
256 E : event_record.Header.ProcessId = file_header.process_id;
257 E : event_record.Header.ThreadId = segment_header.thread_id;
258 E : event_record.Header.Guid = kCallTraceEventClass;
259 :
260 E : uint8* read_ptr = buffer;
261 E : uint8* end_ptr = read_ptr + buffer_length;
262 :
263 E : while (read_ptr < end_ptr) {
264 E : RecordPrefix* prefix = reinterpret_cast<RecordPrefix*>(read_ptr);
265 E : read_ptr += sizeof(RecordPrefix) + prefix->size;
266 E : if (read_ptr > end_ptr) {
267 : // For batch-oriented records (where the record size is updated after
268 : // the record is initially written) there's a race condition between
269 : // updating the size of the segment and updating the number of items
270 : // in the batch record wherein the client process could be terminated
271 : // leaving a truncated batch record.
272 i : LOG(WARNING) << "Encountered truncated record at end of segment.";
273 i : continue;
274 : }
275 :
276 E : event_record.Header.Class.Type = prefix->type;
277 :
278 : // The TimeStamp is interpreted as a FILETIME, so we convert the timer
279 : // value to that.
280 : trace::common::TscToFileTime(
281 : file_header.clock_info,
282 : prefix->timestamp,
283 E : reinterpret_cast<FILETIME*>(&event_record.Header.TimeStamp));
284 :
285 E : event_record.MofData = prefix + 1;
286 E : event_record.MofLength = prefix->size;
287 E : if (!DispatchEvent(&event_record)) {
288 i : LOG(ERROR) << "Failed to process event of type " << prefix->type << ".";
289 i : return false;
290 : }
291 :
292 E : if (error_occurred()) {
293 i : return false;
294 : }
295 E : }
296 :
297 E : return true;
298 E : }
299 :
300 : } // namespace parser
301 : } // namespace trace
|