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