1// Copyright 2013 The Chromium Authors. All rights reserved.
2// Use of this source code is governed by a BSD-style license that can be
3// found in the LICENSE file.
4
5#include "chrome/browser/extensions/api/log_private/log_private_api.h"
6
7#include <string>
8#include <vector>
9
10#include "base/command_line.h"
11#include "base/json/json_writer.h"
12#include "base/lazy_instance.h"
13#include "base/logging.h"
14#include "base/memory/linked_ptr.h"
15#include "base/memory/scoped_ptr.h"
16#include "chrome/browser/browser_process.h"
17#include "chrome/browser/download/download_prefs.h"
18#include "chrome/browser/extensions/api/file_handlers/app_file_handler_util.h"
19#include "chrome/browser/extensions/api/log_private/filter_handler.h"
20#include "chrome/browser/extensions/api/log_private/log_parser.h"
21#include "chrome/browser/extensions/api/log_private/syslog_parser.h"
22#include "chrome/browser/feedback/system_logs/scrubbed_system_logs_fetcher.h"
23#include "chrome/browser/io_thread.h"
24#include "chrome/browser/net/chrome_net_log.h"
25#include "chrome/browser/profiles/profile.h"
26#include "chrome/browser/profiles/profile_manager.h"
27#include "chrome/common/extensions/api/log_private.h"
28#include "chrome/common/logging_chrome.h"
29#include "content/public/browser/render_process_host.h"
30#include "extensions/browser/event_router.h"
31#include "extensions/browser/extension_function.h"
32#include "extensions/browser/extension_registry.h"
33#include "extensions/browser/granted_file_entry.h"
34
35#if defined(OS_CHROMEOS)
36#include "chrome/browser/chromeos/system_logs/debug_log_writer.h"
37#endif
38
39using content::BrowserThread;
40
41namespace events {
42const char kOnCapturedEvents[] = "logPrivate.onCapturedEvents";
43}  // namespace events
44
45namespace extensions {
46namespace {
47
48const char kAppLogsSubdir[] = "apps";
49const char kLogDumpsSubdir[] = "log_dumps";
50const char kLogFileNameBase[] = "net-internals";
51const int kNetLogEventDelayMilliseconds = 100;
52
53// Gets sequenced task runner for file specific calls within this API.
54scoped_refptr<base::SequencedTaskRunner> GetSequencedTaskRunner() {
55  base::SequencedWorkerPool* pool = BrowserThread::GetBlockingPool();
56  return pool->GetSequencedTaskRunnerWithShutdownBehavior(
57      pool->GetNamedSequenceToken(FileResource::kSequenceToken),
58      base::SequencedWorkerPool::BLOCK_SHUTDOWN);
59}
60
61// Checks if we are running on sequenced task runner thread.
62bool IsRunningOnSequenceThread() {
63  base::SequencedWorkerPool* pool = content::BrowserThread::GetBlockingPool();
64  return pool->IsRunningSequenceOnCurrentThread(
65      pool->GetNamedSequenceToken(FileResource::kSequenceToken));
66}
67
68scoped_ptr<LogParser> CreateLogParser(const std::string& log_type) {
69  if (log_type == "syslog")
70    return scoped_ptr<LogParser>(new SyslogParser());
71  // TODO(shinfan): Add more parser here
72
73  NOTREACHED() << "Invalid log type: " << log_type;
74  return  scoped_ptr<LogParser>();
75}
76
77void CollectLogInfo(
78    FilterHandler* filter_handler,
79    system_logs::SystemLogsResponse* logs,
80    std::vector<linked_ptr<api::log_private::LogEntry> >* output) {
81  for (system_logs::SystemLogsResponse::const_iterator
82      request_it = logs->begin(); request_it != logs->end(); ++request_it) {
83    if (!filter_handler->IsValidSource(request_it->first)) {
84      continue;
85    }
86    scoped_ptr<LogParser> parser(CreateLogParser(request_it->first));
87    if (parser) {
88      parser->Parse(request_it->second, output, filter_handler);
89    }
90  }
91}
92
93// Returns directory location of app-specific logs that are initiated with
94// logPrivate.startEventRecorder() calls - /home/chronos/user/log/apps
95base::FilePath GetAppLogDirectory() {
96  return logging::GetSessionLogDir(*CommandLine::ForCurrentProcess())
97      .Append(kAppLogsSubdir);
98}
99
100// Returns directory location where logs dumps initiated with chrome.dumpLogs
101// will be stored - /home/chronos/<user_profile_dir>/Downloads/log_dumps
102base::FilePath GetLogDumpDirectory(content::BrowserContext* context) {
103  const DownloadPrefs* const prefs = DownloadPrefs::FromBrowserContext(context);
104  return prefs->DownloadPath().Append(kLogDumpsSubdir);
105}
106
107// Removes direcotry content of |logs_dumps| and |app_logs_dir| (only for the
108// primary profile).
109void CleanUpLeftoverLogs(bool is_primary_profile,
110                         const base::FilePath& app_logs_dir,
111                         const base::FilePath& logs_dumps) {
112  LOG(WARNING) << "Deleting " << app_logs_dir.value();
113  LOG(WARNING) << "Deleting " << logs_dumps.value();
114
115  DCHECK(IsRunningOnSequenceThread());
116  base::DeleteFile(logs_dumps, true);
117
118  // App-specific logs are stored in /home/chronos/user/log/apps directory that
119  // is shared between all profiles in multi-profile case. We should not
120  // nuke it for non-primary profiles.
121  if (!is_primary_profile)
122    return;
123
124  base::DeleteFile(app_logs_dir, true);
125}
126
127}  // namespace
128
129const char FileResource::kSequenceToken[] = "log_api_files";
130
131FileResource::FileResource(const std::string& owner_extension_id,
132                           const base::FilePath& path)
133    : ApiResource(owner_extension_id), path_(path) {
134}
135
136FileResource::~FileResource() {
137  base::DeleteFile(path_, true);
138}
139
140bool FileResource::IsPersistent() const {
141  return false;
142}
143
144// static
145LogPrivateAPI* LogPrivateAPI::Get(content::BrowserContext* context) {
146  LogPrivateAPI* api = GetFactoryInstance()->Get(context);
147  api->Initialize();
148  return api;
149}
150
151LogPrivateAPI::LogPrivateAPI(content::BrowserContext* context)
152    : browser_context_(context),
153      logging_net_internals_(false),
154      event_sink_(api::log_private::EVENT_SINK_CAPTURE),
155      extension_registry_observer_(this),
156      log_file_resources_(context),
157      initialized_(false) {
158}
159
160LogPrivateAPI::~LogPrivateAPI() {
161}
162
163void LogPrivateAPI::StartNetInternalsWatch(
164    const std::string& extension_id,
165    api::log_private::EventSink event_sink,
166    const base::Closure& closure) {
167  net_internal_watches_.insert(extension_id);
168
169  // Nuke any leftover app-specific or dumped log files from previous sessions.
170  BrowserThread::PostTaskAndReply(
171      BrowserThread::IO,
172      FROM_HERE,
173      base::Bind(&LogPrivateAPI::MaybeStartNetInternalLogging,
174                 base::Unretained(this),
175                 extension_id,
176                 g_browser_process->io_thread(),
177                 event_sink),
178      closure);
179}
180
181void LogPrivateAPI::StopNetInternalsWatch(const std::string& extension_id,
182                                          const base::Closure& closure) {
183  net_internal_watches_.erase(extension_id);
184  MaybeStopNetInternalLogging(closure);
185}
186
187void LogPrivateAPI::StopAllWatches(const std::string& extension_id,
188                                   const base::Closure& closure) {
189  StopNetInternalsWatch(extension_id, closure);
190}
191
192void LogPrivateAPI::RegisterTempFile(const std::string& owner_extension_id,
193                                     const base::FilePath& file_path) {
194  if (!IsRunningOnSequenceThread()) {
195    GetSequencedTaskRunner()->PostTask(
196        FROM_HERE,
197        base::Bind(&LogPrivateAPI::RegisterTempFile,
198                   base::Unretained(this),
199                   owner_extension_id,
200                   file_path));
201    return;
202  }
203
204  log_file_resources_.Add(new FileResource(owner_extension_id, file_path));
205}
206
207static base::LazyInstance<BrowserContextKeyedAPIFactory<LogPrivateAPI> >
208    g_factory = LAZY_INSTANCE_INITIALIZER;
209
210// static
211BrowserContextKeyedAPIFactory<LogPrivateAPI>*
212LogPrivateAPI::GetFactoryInstance() {
213  return g_factory.Pointer();
214}
215
216void LogPrivateAPI::OnAddEntry(const net::NetLog::Entry& entry) {
217  // We could receive events on whatever thread they happen to be generated,
218  // since we are only interested in network events, we should ignore any
219  // other thread than BrowserThread::IO.
220  if (!BrowserThread::CurrentlyOn(BrowserThread::IO)) {
221    return;
222  }
223
224  if (!pending_entries_.get()) {
225    pending_entries_.reset(new base::ListValue());
226    BrowserThread::PostDelayedTask(
227        BrowserThread::IO, FROM_HERE,
228        base::Bind(&LogPrivateAPI::PostPendingEntries, base::Unretained(this)),
229        base::TimeDelta::FromMilliseconds(kNetLogEventDelayMilliseconds));
230  }
231  pending_entries_->Append(entry.ToValue());
232}
233
234void LogPrivateAPI::PostPendingEntries() {
235  BrowserThread::PostTask(
236      BrowserThread::UI, FROM_HERE,
237      base::Bind(&LogPrivateAPI:: AddEntriesOnUI,
238                 base::Unretained(this),
239                 base::Passed(&pending_entries_)));
240}
241
242void LogPrivateAPI::AddEntriesOnUI(scoped_ptr<base::ListValue> value) {
243  DCHECK_CURRENTLY_ON(BrowserThread::UI);
244
245  for (std::set<std::string>::iterator ix = net_internal_watches_.begin();
246       ix != net_internal_watches_.end(); ++ix) {
247    // Create the event's arguments value.
248    scoped_ptr<base::ListValue> event_args(new base::ListValue());
249    event_args->Append(value->DeepCopy());
250    scoped_ptr<Event> event(
251        new Event(events::kOnCapturedEvents, event_args.Pass()));
252    EventRouter::Get(browser_context_)
253        ->DispatchEventToExtension(*ix, event.Pass());
254  }
255}
256
257void LogPrivateAPI::InitializeNetLogger(const std::string& owner_extension_id,
258                                        net::NetLogLogger** net_log_logger) {
259  DCHECK(IsRunningOnSequenceThread());
260  (*net_log_logger) = NULL;
261
262  // Create app-specific subdirectory in session logs folder.
263  base::FilePath app_log_dir = GetAppLogDirectory().Append(owner_extension_id);
264  if (!base::DirectoryExists(app_log_dir)) {
265    if (!base::CreateDirectory(app_log_dir)) {
266      LOG(ERROR) << "Could not create dir " << app_log_dir.value();
267      return;
268    }
269  }
270
271  base::FilePath file_path = app_log_dir.Append(kLogFileNameBase);
272  file_path = logging::GenerateTimestampedName(file_path, base::Time::Now());
273  FILE* file = NULL;
274  file = fopen(file_path.value().c_str(), "w");
275  if (file == NULL) {
276    LOG(ERROR) << "Could not open " << file_path.value();
277    return;
278  }
279
280  RegisterTempFile(owner_extension_id, file_path);
281  scoped_ptr<base::Value> constants(net::NetLogLogger::GetConstants());
282  *net_log_logger = new net::NetLogLogger(file, *constants);
283  (*net_log_logger)->set_log_level(net::NetLog::LOG_ALL_BUT_BYTES);
284}
285
286void LogPrivateAPI::StartObservingNetEvents(
287    IOThread* io_thread,
288    net::NetLogLogger** net_log_logger) {
289  DCHECK_CURRENTLY_ON(BrowserThread::IO);
290  if (!(*net_log_logger))
291    return;
292
293  net_log_logger_.reset(*net_log_logger);
294  net_log_logger_->StartObserving(io_thread->net_log());
295}
296
297void LogPrivateAPI::MaybeStartNetInternalLogging(
298    const std::string& caller_extension_id,
299    IOThread* io_thread,
300    api::log_private::EventSink event_sink) {
301  DCHECK_CURRENTLY_ON(BrowserThread::IO);
302  if (!logging_net_internals_) {
303    logging_net_internals_ = true;
304    event_sink_ = event_sink;
305    switch (event_sink_) {
306      case api::log_private::EVENT_SINK_CAPTURE: {
307        io_thread->net_log()->AddThreadSafeObserver(
308            this, net::NetLog::LOG_ALL_BUT_BYTES);
309        break;
310      }
311      case api::log_private::EVENT_SINK_FILE: {
312        net::NetLogLogger** net_logger_ptr = new net::NetLogLogger* [1];
313        // Initialize net logger on the blocking pool and start observing event
314        // with in on IO thread.
315        GetSequencedTaskRunner()->PostTaskAndReply(
316            FROM_HERE,
317            base::Bind(&LogPrivateAPI::InitializeNetLogger,
318                       base::Unretained(this),
319                       caller_extension_id,
320                       net_logger_ptr),
321            base::Bind(&LogPrivateAPI::StartObservingNetEvents,
322                       base::Unretained(this),
323                       io_thread,
324                       base::Owned(net_logger_ptr)));
325        break;
326      }
327      case api::log_private::EVENT_SINK_NONE: {
328        NOTREACHED();
329        break;
330      }
331    }
332  }
333}
334
335void LogPrivateAPI::MaybeStopNetInternalLogging(const base::Closure& closure) {
336  if (net_internal_watches_.empty()) {
337    if (closure.is_null()) {
338      BrowserThread::PostTask(
339          BrowserThread::IO,
340          FROM_HERE,
341          base::Bind(&LogPrivateAPI::StopNetInternalLogging,
342                     base::Unretained(this)));
343    } else {
344      BrowserThread::PostTaskAndReply(
345          BrowserThread::IO,
346          FROM_HERE,
347          base::Bind(&LogPrivateAPI::StopNetInternalLogging,
348                     base::Unretained(this)),
349          closure);
350    }
351  }
352}
353
354void LogPrivateAPI::StopNetInternalLogging() {
355  DCHECK_CURRENTLY_ON(BrowserThread::IO);
356  if (net_log() && logging_net_internals_) {
357    logging_net_internals_ = false;
358    switch (event_sink_) {
359      case api::log_private::EVENT_SINK_CAPTURE:
360        net_log()->RemoveThreadSafeObserver(this);
361        break;
362      case api::log_private::EVENT_SINK_FILE:
363        net_log_logger_->StopObserving();
364        net_log_logger_.reset();
365        break;
366      case api::log_private::EVENT_SINK_NONE:
367        NOTREACHED();
368        break;
369    }
370  }
371}
372
373void LogPrivateAPI::Initialize() {
374  if (initialized_)
375    return;
376
377  // Clean up temp files and folders from the previous sessions.
378  initialized_ = true;
379  extension_registry_observer_.Add(ExtensionRegistry::Get(browser_context_));
380  GetSequencedTaskRunner()->PostTask(
381      FROM_HERE,
382      base::Bind(&CleanUpLeftoverLogs,
383                 Profile::FromBrowserContext(browser_context_) ==
384                     ProfileManager::GetPrimaryUserProfile(),
385                 GetAppLogDirectory(),
386                 GetLogDumpDirectory(browser_context_)));
387}
388
389void LogPrivateAPI::OnExtensionUnloaded(
390    content::BrowserContext* browser_context,
391    const Extension* extension,
392    UnloadedExtensionInfo::Reason reason) {
393  StopNetInternalsWatch(extension->id(), base::Closure());
394}
395
396LogPrivateGetHistoricalFunction::LogPrivateGetHistoricalFunction() {
397}
398
399LogPrivateGetHistoricalFunction::~LogPrivateGetHistoricalFunction() {
400}
401
402bool LogPrivateGetHistoricalFunction::RunAsync() {
403  // Get parameters
404  scoped_ptr<api::log_private::GetHistorical::Params> params(
405      api::log_private::GetHistorical::Params::Create(*args_));
406  EXTENSION_FUNCTION_VALIDATE(params.get());
407  filter_handler_.reset(new FilterHandler(params->filter));
408
409  system_logs::SystemLogsFetcherBase* fetcher;
410  if ((params->filter).scrub) {
411    fetcher = new system_logs::ScrubbedSystemLogsFetcher();
412  } else {
413    fetcher = new system_logs::AboutSystemLogsFetcher();
414  }
415  fetcher->Fetch(
416      base::Bind(&LogPrivateGetHistoricalFunction::OnSystemLogsLoaded, this));
417
418  return true;
419}
420
421void LogPrivateGetHistoricalFunction::OnSystemLogsLoaded(
422    scoped_ptr<system_logs::SystemLogsResponse> sys_info) {
423  std::vector<linked_ptr<api::log_private::LogEntry> > data;
424
425  CollectLogInfo(filter_handler_.get(), sys_info.get(), &data);
426
427  // Prepare result
428  api::log_private::Result result;
429  result.data = data;
430  api::log_private::Filter::Populate(
431      *((filter_handler_->GetFilter())->ToValue()), &result.filter);
432  SetResult(result.ToValue().release());
433  SendResponse(true);
434}
435
436LogPrivateStartEventRecorderFunction::LogPrivateStartEventRecorderFunction() {
437}
438
439LogPrivateStartEventRecorderFunction::~LogPrivateStartEventRecorderFunction() {
440}
441
442bool LogPrivateStartEventRecorderFunction::RunAsync() {
443  scoped_ptr<api::log_private::StartEventRecorder::Params> params(
444      api::log_private::StartEventRecorder::Params::Create(*args_));
445  EXTENSION_FUNCTION_VALIDATE(params.get());
446  switch (params->event_type) {
447    case api::log_private::EVENT_TYPE_NETWORK:
448      LogPrivateAPI::Get(Profile::FromBrowserContext(browser_context()))
449          ->StartNetInternalsWatch(
450              extension_id(),
451              params->sink,
452              base::Bind(
453                  &LogPrivateStartEventRecorderFunction::OnEventRecorderStarted,
454                  this));
455      break;
456    case api::log_private::EVENT_TYPE_NONE:
457      NOTREACHED();
458      return false;
459  }
460
461  return true;
462}
463
464void LogPrivateStartEventRecorderFunction::OnEventRecorderStarted() {
465  SendResponse(true);
466}
467
468LogPrivateStopEventRecorderFunction::LogPrivateStopEventRecorderFunction() {
469}
470
471LogPrivateStopEventRecorderFunction::~LogPrivateStopEventRecorderFunction() {
472}
473
474bool LogPrivateStopEventRecorderFunction::RunAsync() {
475  scoped_ptr<api::log_private::StopEventRecorder::Params> params(
476      api::log_private::StopEventRecorder::Params::Create(*args_));
477  EXTENSION_FUNCTION_VALIDATE(params.get());
478  switch (params->event_type) {
479    case api::log_private::EVENT_TYPE_NETWORK:
480      LogPrivateAPI::Get(Profile::FromBrowserContext(browser_context()))
481          ->StopNetInternalsWatch(
482              extension_id(),
483              base::Bind(
484                  &LogPrivateStopEventRecorderFunction::OnEventRecorderStopped,
485                  this));
486      break;
487    case api::log_private::EVENT_TYPE_NONE:
488      NOTREACHED();
489      return false;
490  }
491  return true;
492}
493
494void LogPrivateStopEventRecorderFunction::OnEventRecorderStopped() {
495  SendResponse(true);
496}
497
498LogPrivateDumpLogsFunction::LogPrivateDumpLogsFunction() {
499}
500
501LogPrivateDumpLogsFunction::~LogPrivateDumpLogsFunction() {
502}
503
504bool LogPrivateDumpLogsFunction::RunAsync() {
505  LogPrivateAPI::Get(Profile::FromBrowserContext(browser_context()))
506      ->StopAllWatches(
507          extension_id(),
508          base::Bind(&LogPrivateDumpLogsFunction::OnStopAllWatches, this));
509  return true;
510}
511
512void LogPrivateDumpLogsFunction::OnStopAllWatches() {
513  chromeos::DebugLogWriter::StoreCombinedLogs(
514      GetLogDumpDirectory(browser_context()).Append(extension_id()),
515      FileResource::kSequenceToken,
516      base::Bind(&LogPrivateDumpLogsFunction::OnStoreLogsCompleted, this));
517}
518
519void LogPrivateDumpLogsFunction::OnStoreLogsCompleted(
520    const base::FilePath& log_path,
521    bool succeeded) {
522  if (succeeded) {
523    LogPrivateAPI::Get(Profile::FromBrowserContext(browser_context()))
524        ->RegisterTempFile(extension_id(), log_path);
525  }
526
527  scoped_ptr<base::DictionaryValue> response(new base::DictionaryValue());
528  extensions::GrantedFileEntry file_entry =
529      extensions::app_file_handler_util::CreateFileEntry(
530          Profile::FromBrowserContext(browser_context()),
531          extension(),
532          render_view_host_->GetProcess()->GetID(),
533          log_path,
534          false);
535
536  base::DictionaryValue* entry = new base::DictionaryValue();
537  entry->SetString("fileSystemId", file_entry.filesystem_id);
538  entry->SetString("baseName", file_entry.registered_name);
539  entry->SetString("id", file_entry.id);
540  entry->SetBoolean("isDirectory", false);
541  base::ListValue* entry_list = new base::ListValue();
542  entry_list->Append(entry);
543  response->Set("entries", entry_list);
544  response->SetBoolean("multiple", false);
545  SetResult(response.release());
546  SendResponse(succeeded);
547}
548
549}  // namespace extensions
550