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