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/rand_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 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 : base::ProcessHandle process_handle;
149 E : base::LaunchOptions options;
150 E : options.start_hidden = false;
151 E : if (!base::LaunchProcess(command_line, options, &process_handle)) {
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 : base::CloseProcessHandle(process_handle);
166 E : return true;
167 : }
168 :
169 : case WAIT_OBJECT_0 + 1: {
170 : // The logger has been shutdown. Kill the client process.
171 i : base::KillProcess(process_handle, 1, true);
172 i : base::CloseProcessHandle(process_handle);
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_(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 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,
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 : CommandLine new_command_line(self_path);
455 i : new_command_line.AppendArg("start");
456 :
457 : // Copy over any other switches.
458 : 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 : base::ProcessHandle service_process;
465 i : base::LaunchOptions options;
466 i : options.start_hidden = true;
467 i : if (!base::LaunchProcess(new_command_line, options, &service_process)) {
468 i : LOG(ERROR) << "Failed to launch process.";
469 i : return false;
470 : }
471 i : DCHECK_NE(base::kNullProcessHandle, service_process);
472 :
473 : // Setup the start event.
474 i : base::win::ScopedHandle start_event;
475 : std::wstring start_event_name(
476 i : GetInstanceString(kLoggerStartEventRoot, instance_id_));
477 i : if (!trace::common::InitEvent(start_event_name, &start_event)) {
478 i : LOG(ERROR) << "Unable to init start event for '" << logger_name << "'.";
479 i : return false;
480 : }
481 :
482 : // We wait on both the start event and the process, as if the process fails
483 : // for any reason, it'll exit and its handle will become signaled.
484 i : HANDLE handles[] = { start_event, service_process };
485 : if (::WaitForMultipleObjects(arraysize(handles),
486 : handles,
487 : FALSE,
488 i : INFINITE) != WAIT_OBJECT_0) {
489 i : LOG(ERROR) << "The logger '" << logger_name << "' exited in error.";
490 i : return false;
491 : }
492 :
493 i : LOG(INFO) << "Background logger '" << logger_name << "' is running.";
494 :
495 i : return true;
496 i : }
497 :
498 E : bool LoggerApp::Stop() {
499 : std::wstring logger_name(
500 E : GetInstanceString(kLoggerRpcEndpointRoot, instance_id_));
501 :
502 : // Setup the stop event.
503 E : base::win::ScopedHandle stop_event;
504 : std::wstring stop_event_name(
505 E : GetInstanceString(kLoggerStopEventRoot, instance_id_));
506 E : if (!trace::common::InitEvent(stop_event_name, &stop_event)) {
507 i : LOG(ERROR) << "Unable to init stop event for '" << logger_name << "'.";
508 i : return false;
509 : }
510 :
511 : // Send the stop request.
512 E : if (!SendStopRequest(instance_id_))
513 i : return false;
514 :
515 : // We wait on both the RPC event and the process, as if the process fails for
516 : // any reason, it'll exit and its handle will become signaled.
517 E : if (::WaitForSingleObject(stop_event, INFINITE) != WAIT_OBJECT_0) {
518 i : LOG(ERROR) << "Timed out waiting for '" << logger_name << "' to stop.";
519 i : return false;
520 : }
521 :
522 E : LOG(INFO) << "The logger instance has stopped.";
523 :
524 E : return true;
525 E : }
526 :
527 : // Helper to resolve @p path to an open file. This will set @p must_close
528 : // to true if @path denotes a newly opened file, and false if it denotes
529 : // stderr or stdout.
530 E : bool LoggerApp::OpenOutputFile(FILE** output_file, bool* must_close) {
531 E : DCHECK(output_file != NULL);
532 E : DCHECK(must_close != NULL);
533 :
534 E : *output_file = NULL;
535 E : *must_close = false;
536 :
537 : // Check for stdout.
538 : if (output_file_path_.empty() ||
539 : ::_wcsnicmp(output_file_path_.value().c_str(),
540 : kStdOut,
541 E : arraysize(kStdOut)) == 0) {
542 E : *output_file = stdout;
543 E : return true;
544 : }
545 :
546 : // Check for stderr.
547 : if (::_wcsnicmp(output_file_path_.value().c_str(),
548 : kStdErr,
549 E : arraysize(kStdErr)) == 0) {
550 i : *output_file = stderr;
551 i : return true;
552 : }
553 :
554 : // Setup the write mode.
555 E : const char* mode = "wb";
556 E : if (append_)
557 i : mode = "ab";
558 :
559 : // Create a new file, which the caller is responsible for closing.
560 E : *output_file = base::OpenFile(output_file_path_, mode);
561 E : if (*output_file == NULL)
562 i : return false;
563 :
564 E : *must_close = true;
565 E : return true;
566 E : }
567 :
568 : // Print the usage/help text, plus an optional @p message.
569 : bool LoggerApp::Usage(const CommandLine* command_line,
570 E : const base::StringPiece& message) const {
571 E : if (!message.empty()) {
572 E : ::fwrite(message.data(), 1, message.length(), err());
573 E : ::fprintf(err(), "\n\n");
574 : }
575 :
576 : ::fprintf(err(),
577 : kUsageFormatStr,
578 E : command_line->GetProgram().BaseName().value().c_str());
579 :
580 E : return false;
581 E : }
582 :
583 : } // namespace agent_logger
584 : } // namespace trace
|