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 : // This file defines the trace::logger::LoggerApp class which implements the
16 : // LoggerApp RPC interface.
17 :
18 : #include "syzygy/trace/logger/logger_app.h"
19 :
20 : #include "base/bind.h"
21 : #include "base/environment.h"
22 : #include "base/file_util.h"
23 : #include "base/path_service.h"
24 : #include "base/process.h"
25 : #include "base/process_util.h"
26 : #include "base/rand_util.h"
27 : #include "base/string_util.h"
28 : #include "base/stringprintf.h"
29 : #include "base/utf_string_conversions.h"
30 : #include "base/win/scoped_handle.h"
31 : #include "syzygy/trace/common/service_util.h"
32 : #include "syzygy/trace/logger/logger.h"
33 : #include "syzygy/trace/logger/logger_rpc_impl.h"
34 : #include "syzygy/trace/protocol/call_trace_defs.h"
35 : #include "syzygy/trace/rpc/logger_rpc.h"
36 : #include "syzygy/trace/rpc/rpc_helpers.h"
37 :
38 : namespace trace {
39 : namespace logger {
40 :
41 : namespace {
42 :
43 : using trace::client::GetInstanceString;
44 :
45 : // The usage string for the logger app.
46 : const char kUsageFormatStr[] =
47 : "Usage: %ls [options] ACTION [-- command]\n"
48 : " Supported actions:\n"
49 : " start Run a new logger instance in the foreground (blocking). You\n"
50 : " may optionally specify an external command which will be\n"
51 : " run behind the logger. The logger will return once the\n"
52 : " external command has terminated or the logger is externally\n"
53 : " stopped. If no command is specified, Ctrl-C or an invocation\n"
54 : " of the stop action will stop the logger.\n"
55 : " spawn Run a new logger instance in the background (non-blocking).\n"
56 : " stop Stop a separately running logger instance.\n"
57 : "\n"
58 : " Options:\n"
59 : " --instance-id=ID A unique (up to 16 character) ID to identify\n"
60 : " the logger instance.\n"
61 : " --minidump-dir=PATH The directory path in which minidumps, if any,\n"
62 : " should be generated.\n"
63 : " --output-file=PATH The file path to which logs should be written.\n"
64 : " This may be stdout (the default), stderr or a\n"
65 : " file path. This option is valid for the start\n"
66 : " and spawn actions.\n"
67 : " --append Append to (instead of truncating) the output\n"
68 : " file. This option is valid for the start and\n"
69 : " spawn actions.\n";
70 :
71 : // Names for kernel objects used to synchronize with a logger singleton.
72 : const wchar_t kLoggerMutexRoot[] = L"syzygy-logger-mutex";
73 : const wchar_t kLoggerStartEventRoot[] = L"syzygy-logger-started";
74 : const wchar_t kLoggerStopEventRoot[] = L"syzygy-logger-stopped";
75 :
76 : // A static location to which the current instance id can be saved. We
77 : // persist it here so that OnConsoleCtrl can have access to the instance
78 : // id when it is invoked on the signal handler thread.
79 : wchar_t saved_instance_id[LoggerApp::kMaxInstanceIdLength + 1] = { 0 };
80 :
81 : // Send a stop request via RPC to the logger instance given by @p instance_id.
82 i : bool SendStopRequest(const base::StringPiece16& instance_id) {
83 i : std::wstring protocol(kLoggerRpcProtocol);
84 i : std::wstring endpoint(GetInstanceString(kLoggerRpcEndpointRoot, instance_id));
85 :
86 i : LOG(INFO) << "Stopping logging service instance at '"
87 : << endpoint << "' via " << protocol << '.';
88 :
89 i : handle_t binding = NULL;
90 i : if (!trace::client::CreateRpcBinding(protocol, endpoint, &binding)) {
91 i : LOG(ERROR) << "Failed to connect to logging service.";
92 i : return false;
93 : }
94 :
95 i : if (!trace::client::InvokeRpc(LoggerClient_Stop, binding).succeeded()) {
96 i : LOG(ERROR) << "Failed to stop logging service.";
97 i : return false;
98 : }
99 :
100 i : LOG(INFO) << "Logging service shutdown has been requested.";
101 :
102 i : return true;
103 i : }
104 :
105 : // Handler function to be called on exit signals (Ctrl-C, TERM, etc...).
106 i : BOOL WINAPI OnConsoleCtrl(DWORD ctrl_type) {
107 i : if (ctrl_type != CTRL_LOGOFF_EVENT) {
108 i : SendStopRequest(saved_instance_id);
109 i : return TRUE;
110 : }
111 i : return FALSE;
112 i : }
113 :
114 : // A helper function to signal an event. This is passable as a callback to
115 : // a Logger instance to be called on logger start/stop.
116 E : bool SignalEvent(HANDLE event_handle, trace::common::Service* /* logger */) {
117 E : DCHECK_NE(INVALID_HANDLE_VALUE, event_handle);
118 E : if (!::SetEvent(event_handle))
119 i : return false;
120 E : return true;
121 E : }
122 :
123 : // A helper function which sets the Syzygy RPC instance id environment variable
124 : // then runs a given command line to completion.
125 : bool RunApp(const CommandLine& command_line,
126 : const std::wstring& instance_id,
127 : HANDLE interruption_event,
128 E : int* exit_code) {
129 E : DCHECK(exit_code != NULL);
130 E : scoped_ptr<base::Environment> env(base::Environment::Create());
131 E : CHECK(env != NULL);
132 E : env->SetVar(kSyzygyRpcInstanceIdEnvVar, WideToUTF8(instance_id));
133 :
134 E : LOG(INFO) << "Launching '" << command_line.GetProgram().value() << "'.";
135 E : VLOG(1) << "Command Line: " << command_line.GetCommandLineString();
136 :
137 E : *exit_code = 0;
138 :
139 : // Launch a new process in the background.
140 : base::ProcessHandle process_handle;
141 E : base::LaunchOptions options;
142 E : options.start_hidden = false;
143 E : if (!base::LaunchProcess(command_line, options, &process_handle)) {
144 i : LOG(ERROR)
145 : << "Failed to launch '" << command_line.GetProgram().value() << "'.";
146 i : return false;
147 : }
148 :
149 E : HANDLE objects[] = { process_handle, interruption_event };
150 E : DWORD num_objects = arraysize(objects);
151 E : switch (::WaitForMultipleObjects(num_objects, objects, FALSE, INFINITE)) {
152 : case WAIT_OBJECT_0 + 0: {
153 : // The client process has finished.
154 : DWORD temp_exit_code;
155 E : ::GetExitCodeProcess(process_handle, &temp_exit_code);
156 E : *exit_code = temp_exit_code;
157 E : base::CloseProcessHandle(process_handle);
158 E : return true;
159 : }
160 :
161 : case WAIT_OBJECT_0 + 1: {
162 : // The logger has been shutdown. Kill the client process.
163 i : base::KillProcess(process_handle, 1, true);
164 i : base::CloseProcessHandle(process_handle);
165 i : *exit_code = 1;
166 i : return true;
167 : }
168 : }
169 :
170 : // If we get here then an error has occurred (since the timeout is infinite).
171 i : DWORD error = ::GetLastError();
172 i : LOG(ERROR) << "Error waiting for shutdown event " << com::LogWe(error) << ".";
173 i : return false;
174 E : }
175 :
176 : } // namespace
177 :
178 : // Keywords appearing on the command-line
179 : const wchar_t LoggerApp::kSpawn[] = L"spawn";
180 : const wchar_t LoggerApp::kStart[] = L"start";
181 : const wchar_t LoggerApp::kStatus[] = L"status";
182 : const wchar_t LoggerApp::kStop[] = L"stop";
183 : const char LoggerApp::kInstanceId[] = "instance-id";
184 : const char LoggerApp::kUniqueInstanceId[] = "unique-instance-id";
185 : const char LoggerApp::kOutputFile[] = "output-file";
186 : const char LoggerApp::kMiniDumpDir[] = "minidump-dir";
187 : const char LoggerApp::kAppend[] = "append";
188 : const wchar_t LoggerApp::kStdOut[] = L"stdout";
189 : const wchar_t LoggerApp::kStdErr[] = L"stderr";
190 :
191 : // A table mapping action keywords to their handler implementations.
192 E : const LoggerApp::ActionTableEntry LoggerApp::kActionTable[] = {
193 E : { LoggerApp::kSpawn, &LoggerApp::Spawn },
194 E : { LoggerApp::kStart, &LoggerApp::Start },
195 E : { LoggerApp::kStatus, &LoggerApp::Status },
196 E : { LoggerApp::kStop, &LoggerApp::Stop },
197 E : };
198 :
199 : LoggerApp::LoggerApp()
200 : : ::common::AppImplBase("Logger"),
201 : logger_command_line_(CommandLine::NO_PROGRAM),
202 : action_handler_(NULL),
203 E : append_(false) {
204 E : }
205 :
206 E : LoggerApp::~LoggerApp() {
207 E : }
208 :
209 E : bool LoggerApp::ParseCommandLine(const CommandLine* command_line) {
210 E : DCHECK(command_line != NULL);
211 :
212 : if (!trace::common::SplitCommandLine(
213 : command_line,
214 : &logger_command_line_,
215 E : &app_command_line_)) {
216 i : LOG(ERROR) << "Failed to split command_line into logger and app parts.";
217 i : return false;
218 : }
219 :
220 : // Save the command-line in case we need to spawn.
221 E : command_line = &logger_command_line_;
222 :
223 : if (command_line->HasSwitch(kInstanceId) &&
224 E : command_line->HasSwitch(kUniqueInstanceId)) {
225 : return Usage(command_line,
226 : base::StringPrintf("--%s and --%s are mutually exclusive.",
227 : kInstanceId,
228 i : kUniqueInstanceId));
229 : }
230 :
231 : // Parse the instance id.
232 E : instance_id_ = command_line->GetSwitchValueNative(kInstanceId);
233 E : if (instance_id_.length() > kMaxInstanceIdLength) {
234 : return Usage(command_line,
235 : base::StringPrintf("The instance id '%ls' is too long. "
236 : "The max length is %d characters.",
237 : instance_id_.c_str(),
238 i : kMaxInstanceIdLength));
239 : }
240 :
241 : // Save the output file parameter.
242 E : output_file_path_ = command_line->GetSwitchValuePath(kOutputFile);
243 :
244 : // Save the minidump-dir parameter.
245 E : mini_dump_dir_ = command_line->GetSwitchValuePath(kMiniDumpDir);
246 E : if (mini_dump_dir_.empty()) {
247 E : CHECK(PathService::Get(base::DIR_CURRENT, &mini_dump_dir_));
248 E : } else {
249 E : mini_dump_dir_ = base::MakeAbsoluteFilePath(mini_dump_dir_);
250 E : if (mini_dump_dir_.empty())
251 i : return Usage(command_line, "The minidump-dir parameter is invalid.");
252 :
253 : if (!file_util::DirectoryExists(mini_dump_dir_) &&
254 E : !file_util::CreateDirectory(mini_dump_dir_)) {
255 i : LOG(ERROR) << "Failed to create minidump-dir "
256 : << mini_dump_dir_.value();
257 : }
258 : }
259 :
260 : // Make sure there's exactly one action.
261 E : if (command_line->GetArgs().size() != 1) {
262 : return Usage(command_line,
263 E : "Exactly 1 action is expected on the command line.");
264 : }
265 :
266 : // Check for the append flag.
267 E : append_ = command_line->HasSwitch(kAppend);
268 :
269 : // Parse the action.
270 E : action_ = command_line->GetArgs()[0];
271 E : const ActionTableEntry* entry = FindActionHandler(action_);
272 E : if (entry == NULL) {
273 : return Usage(
274 : command_line,
275 E : base::StringPrintf("Unrecognized action: %s.", action_.c_str()));
276 : }
277 :
278 E : if (command_line->HasSwitch(kUniqueInstanceId)) {
279 E : DWORD process_id = ::GetCurrentProcessId();
280 E : DWORD timestamp = ::GetTickCount();
281 E : base::SStringPrintf(&instance_id_, L"%08x%08x", process_id, timestamp);
282 E : DCHECK_EQ(kMaxInstanceIdLength, instance_id_.length());
283 : }
284 :
285 E : LOG(INFO) << "Using logger instance ID: '" << instance_id_ << "'.";
286 E : LOG(INFO) << "Writing minidumps to: " << mini_dump_dir_.value();
287 :
288 : // Setup the action handler.
289 E : DCHECK(entry->handler != NULL);
290 E : action_handler_ = entry->handler;
291 :
292 E : return true;
293 E : }
294 :
295 E : int LoggerApp::Run() {
296 E : DCHECK(action_handler_ != NULL);
297 E : if (!(this->*action_handler_)())
298 i : return 1;
299 E : return 0;
300 E : }
301 :
302 : // A helper function to find the handler method for a given action.
303 : const LoggerApp::ActionTableEntry* LoggerApp::FindActionHandler(
304 E : const base::StringPiece16& action) {
305 E : for (int i = 0; i < arraysize(kActionTable); ++i) {
306 E : if (::_wcsicmp(kActionTable[i].action, action.data()) == 0)
307 E : return &kActionTable[i];
308 E : }
309 E : return NULL;
310 E : }
311 :
312 E : bool LoggerApp::Start() {
313 : std::wstring logger_name(
314 E : GetInstanceString(kLoggerRpcEndpointRoot, instance_id_));
315 :
316 : // Acquire the logger mutex.
317 E : base::win::ScopedHandle mutex;
318 E : std::wstring mutex_name(GetInstanceString(kLoggerMutexRoot, instance_id_));
319 E : if (!trace::common::AcquireMutex(mutex_name, &mutex))
320 i : return false;
321 :
322 : // Setup the start event.
323 E : base::win::ScopedHandle start_event;
324 : std::wstring start_event_name(
325 E : GetInstanceString(kLoggerStartEventRoot, instance_id_));
326 E : if (!trace::common::InitEvent(start_event_name, &start_event)) {
327 i : LOG(ERROR) << "Unable to init start event for '" << logger_name << "'.";
328 i : return false;
329 : }
330 :
331 : // Setup the stop event.
332 E : base::win::ScopedHandle stop_event;
333 : std::wstring stop_event_name(
334 E : GetInstanceString(kLoggerStopEventRoot, instance_id_));
335 E : if (!trace::common::InitEvent(stop_event_name, &stop_event)) {
336 i : LOG(ERROR) << "Unable to init stop event for '" << logger_name << "'.";
337 i : return false;
338 : }
339 :
340 : // Setup an anonymous event to notify us if the logger has been
341 : // asynchronously asked to shutdown.
342 E : base::win::ScopedHandle interrupt_event;
343 E : if (!trace::common::InitEvent(L"", &interrupt_event)) {
344 i : LOG(ERROR) << "Unable to init interrupt event for '" << logger_name << "'.";
345 i : return false;
346 : }
347 :
348 : // Get the log file output_file.
349 E : FILE* output_file = NULL;
350 E : bool must_close_output_file = false;
351 E : file_util::ScopedFILE auto_close;
352 E : if (!OpenOutputFile(&output_file, &must_close_output_file)) {
353 i : LOG(ERROR) << "Unable to open '" << output_file_path_.value() << "'.";
354 i : return false;
355 : }
356 :
357 : // Setup auto_close as appropriate.
358 E : if (must_close_output_file)
359 i : auto_close.reset(output_file);
360 :
361 : // Initialize the logger instance.
362 E : Logger logger;
363 E : logger.set_destination(output_file);
364 E : logger.set_minidump_dir(mini_dump_dir_);
365 E : logger.set_instance_id(instance_id_);
366 : logger.set_started_callback(
367 E : base::Bind(&SignalEvent, start_event.Get()));
368 : logger.set_stopped_callback(
369 E : base::Bind(&SignalEvent, stop_event.Get()));
370 : logger.set_interrupted_callback(
371 E : base::Bind(&SignalEvent, interrupt_event.Get()));
372 :
373 : // Save the instance_id for the Ctrl-C handler.
374 : ::wcsncpy_s(saved_instance_id,
375 : arraysize(saved_instance_id),
376 : instance_id_.c_str(),
377 E : -1);
378 :
379 : // Register the handler for Ctrl-C.
380 E : if (!SetConsoleCtrlHandler(&OnConsoleCtrl, TRUE)) {
381 i : DWORD error = ::GetLastError();
382 i : LOG(ERROR) << "Failed to register shutdown handler: "
383 : << com::LogWe(error) << ".";
384 i : return false;
385 : }
386 :
387 : // Start the logger.
388 E : RpcLoggerInstanceManager instance_manager(&logger);
389 E : if (!logger.Start()) {
390 i : LOG(ERROR) << "Failed to start '" << logger_name << "'.";
391 i : return false;
392 : }
393 :
394 E : bool error = false;
395 :
396 : // Run the logger, either standalone or as the parent of some application.
397 E : trace::common::ScopedConsoleCtrlHandler ctrl_handler;
398 E : if (app_command_line_.get() != NULL) {
399 : // We have a command to run, so launch that command and when it finishes
400 : // stop the logger.
401 E : int exit_code = 0;
402 : if (!RunApp(*app_command_line_, instance_id_, interrupt_event,
403 : &exit_code) ||
404 E : exit_code != 0) {
405 i : error = true;
406 : }
407 E : ignore_result(logger.Stop());
408 E : } else {
409 : // There is no command to wait for, so just register the control handler
410 : // (we stop the logger if this fails) and then let the logger run until
411 : // the control handler stops it or someone externally stops it using the
412 : // stop command.
413 i : if (!ctrl_handler.Init(&OnConsoleCtrl)) {
414 i : ignore_result(logger.Stop());
415 i : error = true;
416 : }
417 : }
418 :
419 : // Run the logger to completion.
420 E : if (!logger.Join()) {
421 i : LOG(ERROR) << "Failed running to completion '" << logger_name << "'.";
422 i : error = true;
423 : }
424 :
425 : // And we're done.
426 E : return !error;
427 E : }
428 :
429 i : bool LoggerApp::Status() {
430 : // TODO(rogerm): Implement me.
431 i : return false;
432 i : }
433 :
434 i : bool LoggerApp::Spawn() {
435 : std::wstring logger_name(
436 i : GetInstanceString(kLoggerRpcEndpointRoot, instance_id_));
437 :
438 i : LOG(INFO) << "Launching background logging service '" << logger_name << "'.";
439 :
440 : // Get the path to ourselves.
441 i : base::FilePath self_path;
442 i : PathService::Get(base::FILE_EXE, &self_path);
443 :
444 : // Build a command line for starting a new instance of the logger.
445 i : CommandLine new_command_line(self_path);
446 i : new_command_line.AppendArg("start");
447 :
448 : // Copy over any other switches.
449 : CommandLine::SwitchMap::const_iterator it =
450 i : logger_command_line_.GetSwitches().begin();
451 i : for (; it != logger_command_line_.GetSwitches().end(); ++it)
452 i : new_command_line.AppendSwitchNative(it->first, it->second);
453 :
454 : // Launch a new process in the background.
455 : base::ProcessHandle service_process;
456 i : base::LaunchOptions options;
457 i : options.start_hidden = true;
458 i : if (!base::LaunchProcess(new_command_line, options, &service_process)) {
459 i : LOG(ERROR) << "Failed to launch process.";
460 i : return false;
461 : }
462 i : DCHECK_NE(base::kNullProcessHandle, service_process);
463 :
464 : // Setup the start event.
465 i : base::win::ScopedHandle start_event;
466 : std::wstring start_event_name(
467 i : GetInstanceString(kLoggerStartEventRoot, instance_id_));
468 i : if (!trace::common::InitEvent(start_event_name, &start_event)) {
469 i : LOG(ERROR) << "Unable to init start event for '" << logger_name << "'.";
470 i : return false;
471 : }
472 :
473 : // We wait on both the start event and the process, as if the process fails
474 : // for any reason, it'll exit and its handle will become signaled.
475 i : HANDLE handles[] = { start_event, service_process };
476 : if (::WaitForMultipleObjects(arraysize(handles),
477 : handles,
478 : FALSE,
479 i : INFINITE) != WAIT_OBJECT_0) {
480 i : LOG(ERROR) << "The logger '" << logger_name << "' exited in error.";
481 i : return false;
482 : }
483 :
484 i : LOG(INFO) << "Background logger '" << logger_name << "' is running.";
485 :
486 i : return true;
487 i : }
488 :
489 i : bool LoggerApp::Stop() {
490 : std::wstring logger_name(
491 i : GetInstanceString(kLoggerRpcEndpointRoot, instance_id_));
492 :
493 : // Setup the stop event.
494 i : base::win::ScopedHandle stop_event;
495 : std::wstring stop_event_name(
496 i : GetInstanceString(kLoggerStopEventRoot, instance_id_));
497 i : if (!trace::common::InitEvent(stop_event_name, &stop_event)) {
498 i : LOG(ERROR) << "Unable to init stop event for '" << logger_name << "'.";
499 i : return false;
500 : }
501 :
502 : // Send the stop request.
503 i : if (!SendStopRequest(instance_id_))
504 i : return false;
505 :
506 : // We wait on both the RPC event and the process, as if the process fails for
507 : // any reason, it'll exit and its handle will become signaled.
508 i : if (::WaitForSingleObject(stop_event, INFINITE) != WAIT_OBJECT_0) {
509 i : LOG(ERROR) << "Timed out waiting for '" << logger_name << "' to stop.";
510 i : return false;
511 : }
512 :
513 i : LOG(INFO) << "The logger instance has stopped.";
514 :
515 i : return true;
516 i : }
517 :
518 : // Helper to resolve @p path to an open file. This will set @p must_close
519 : // to true if @path denotes a newly opened file, and false if it denotes
520 : // stderr or stdout.
521 E : bool LoggerApp::OpenOutputFile(FILE** output_file, bool* must_close) {
522 E : DCHECK(output_file != NULL);
523 E : DCHECK(must_close != NULL);
524 :
525 E : *output_file = NULL;
526 E : *must_close = false;
527 :
528 : // Check for stdout.
529 : if (output_file_path_.empty() ||
530 : ::_wcsnicmp(output_file_path_.value().c_str(),
531 : kStdOut,
532 E : arraysize(kStdOut)) == 0) {
533 E : *output_file = stdout;
534 E : return true;
535 : }
536 :
537 : // Check for stderr.
538 : if (::_wcsnicmp(output_file_path_.value().c_str(),
539 : kStdErr,
540 i : arraysize(kStdErr)) == 0) {
541 i : *output_file = stderr;
542 i : return true;
543 : }
544 :
545 : // Setup the write mode.
546 i : const char* mode = "wb";
547 i : if (append_)
548 i : mode = "ab";
549 :
550 : // Create a new file, which the caller is responsible for closing.
551 i : *output_file = file_util::OpenFile(output_file_path_, mode);
552 i : if (*output_file == NULL)
553 i : return false;
554 :
555 i : *must_close = true;
556 i : return true;
557 E : }
558 :
559 : // Print the usage/help text, plus an optional @p message.
560 : bool LoggerApp::Usage(const CommandLine* command_line,
561 E : const base::StringPiece& message) const {
562 E : if (!message.empty()) {
563 E : ::fwrite(message.data(), 1, message.length(), err());
564 E : ::fprintf(err(), "\n\n");
565 : }
566 :
567 : ::fprintf(err(),
568 : kUsageFormatStr,
569 E : command_line->GetProgram().BaseName().value().c_str());
570 :
571 E : return false;
572 E : }
573 :
574 : } // namespace logger
575 : } // namespace trace
|