public/lib/app/dart/src/logging.dart

// Copyright 2017 The Fuchsia Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

import 'dart:async';
import 'dart:convert';
import 'dart:developer' show Timeline;
import 'dart:io';
import 'dart:isolate';
import 'dart:math';
import 'dart:typed_data';

import 'package:fidl_fuchsia_logger/fidl.dart' show LogSinkProxy;
import 'package:fidl_fuchsia_logger/fidl_async.dart' as logger_async
    show LogSinkProxy;
import 'package:lib.app.dart/app.dart' show connectToService, StartupContext;
import 'package:lib.app.dart/app_async.dart' as app_async
    show connectToService, StartupContext;
import 'package:logging/logging.dart' show Level;
import 'package:stack_trace/stack_trace.dart';
import 'package:zircon/zircon.dart' as zircon;

import 'fuchsia_log_record.dart';
import 'fuchsia_logger.dart';

const int _maxGlobalTags = 3;
const int _maxCombinedTags = 5;
const int _maxTagLength = 63;

const int _socketBufferLength = 2032;

final Map<Level, int> _enumToFuchsiaLevelMap = <Level, int>{
  Level.FINEST: -4,
  Level.FINER: -3,
  Level.FINE: -2,
  Level.CONFIG: -1,
  Level.INFO: 0,
  Level.WARNING: 1,
  Level.SEVERE: 2,
  Level.SHOUT: 3,
};
const int _unexpectedLoggingLevel = 100;

/// Method to write a single log message to a single output medium.
/// Solutions are provided to write to stdout and a fuchsia Socket.
typedef LogWriter = void Function(LogWriterMessage message);

/// Interim method that sets up the logger using the new-style bindings for service resolution.
void setupLoggerAsync({
  String name,
  Level level,
  bool forceShowCodeLocation,
  bool logToStdoutForTest,
  List<String> globalTags,
  zircon.Socket logSocket,
  LogWriter logWriter,
}) {
  FutureOr<zircon.Socket> sock;
  if (logSocket == null) {
    final socketPair = zircon.SocketPair(zircon.Socket.DATAGRAM);
    final logSinkProxy = logger_async.LogSinkProxy();

    final completer = Completer<zircon.Socket>();

    app_async
        .connectToService(
          app_async.StartupContext.fromStartupInfo().environmentServices,
          logSinkProxy.ctrl,
        )
        .then((_) => logSinkProxy.connect(socketPair.second))
        .then((_) => completer.complete(socketPair.first))
        .catchError(completer.completeError);

    sock = completer.future;
  } else {
    sock = logSocket;
  }

  setupLogger(
      name: name,
      level: level,
      forceShowCodeLocation: forceShowCodeLocation,
      logToStdoutForTest: logToStdoutForTest,
      globalTags: globalTags,
      logSocket: sock,
      logWriter: logWriter);
}

/// Sets up the default logger for the current Dart application.
///
/// Every Dart application should call this [setupLogger] function in their main
/// before calling the actual log statements.
///
/// The provided [name] will be used for displaying the scope, and this name
/// will default to the last segment (i.e. basename) of the application url.
///
/// If [level] is provided, only the log messages of which level is greater than
/// equal to the provided [level] will be shown. If not provided, it defaults to
/// [Level.INFO].
///
/// By default, the caller code location is automatically added in checked mode
/// and not in production mode, because it is relatively expensive to calculate
/// the code location. If [forceShowCodeLocation] is set to true, the location
/// will be added in production mode as well.
///
/// If [globalTags] is provided, these tags will be added to each message logged
/// via this logger.
///
/// [logToStdoutForTest] will redirect log output to stdout. This should only be
/// used when debugging tests that run on device to mix the log output with
/// the messages from the test infrastructure. It has no effect for on-host
/// tests and should not be included in production code.
///
/// [logWriter] and [logSocket] are intended only for testing purposes.
void setupLogger({
  String name,
  Level level,
  bool forceShowCodeLocation,
  bool logToStdoutForTest,
  List<String> globalTags,
  FutureOr<zircon.Socket> logSocket,
  LogWriter logWriter,
}) {
  final String scopeName = name ??
      Platform.script?.pathSegments?.lastWhere((_) => true, orElse: () => null);
  final List<String> approvedTags = _verifyGlobalTags(globalTags);

  log = FuchsiaLogger(level ?? Level.ALL);

  // This code decides how to log messages. Here's the why:
  // If not running on zircon, there is no sys_logger so must use stdout.
  // The author can force stdout via flag to assist is debugging tests.
  // logSocket and logWriter are used for internal logging tests.
  LogWriter activeLogWriter;
  if (logWriter != null) {
    activeLogWriter = logWriter;
  } else if (logToStdoutForTest != true &&
      (Platform.isFuchsia || logSocket != null)) {
    _logSocket = logSocket ?? _connectToLoggerSocket();
    activeLogWriter = writeLogToSocket;
  } else {
    activeLogWriter = writeLogToStdout;
  }
  _loggerName = scopeName;

  bool inCheckedMode = false;
  assert(() {
    inCheckedMode = true;
    return true;
  }());

  log.onRecord.listen((FuchsiaLogRecord rec) {
    String codeLocation;
    if (forceShowCodeLocation ?? inCheckedMode) {
      final Trace trace = Trace.current();
      final Frame callerFrame = _findCallerFrame(trace);
      if (callerFrame != null) {
        if (callerFrame.uri.pathSegments.isNotEmpty) {
          final String filename = callerFrame.uri.pathSegments.last;
          final String line =
              callerFrame.line != null ? '(${callerFrame.line})' : '';
          codeLocation = '$filename$line';
        }
      }
    }

    activeLogWriter(LogWriterMessage(
      logRecord: rec,
      scopeName: scopeName,
      codeLocation: codeLocation,
      tags: approvedTags,
    ));
  });
}

/// Create a Socket and connect it to the FIDL logger
zircon.Socket _connectToLoggerSocket() {
  final socketPair = zircon.SocketPair(zircon.Socket.DATAGRAM);
  final logSinkProxy = LogSinkProxy();
  connectToService(
    StartupContext.fromStartupInfo().environmentServices,
    logSinkProxy.ctrl,
  );
  logSinkProxy.connect(socketPair.second);
  return socketPair.first;
}

/// All information required to construct a log message to either stdout or
/// Zircon logging Socket.
class LogWriterMessage {
  /// Log record created by fuchsiaLogger
  final FuchsiaLogRecord logRecord;

  /// Name from the logger, typically the module name
  final String scopeName;

  /// If specified, file name and line number where this log message originated
  final String codeLocation;

  /// Identifying tags to associate with this logging message
  final List<String> tags;

  /// Constructor
  LogWriterMessage(
      {this.logRecord, this.scopeName, this.codeLocation, this.tags});
}

/// The default logger to be used by dart applications. Each application should
/// call [setupLogger()] in their main function to properly configure it.
FuchsiaLogger log = FuchsiaLogger(Level.ALL)
  ..onRecord.listen((FuchsiaLogRecord rec) {
    print('WARNING: The logger is not initialized properly.');
    print('WARNING: Please call setupLogger() from your main function.');
    print('[${rec.level}] ${rec.message}');
  });

/// The name of the logger.
String _loggerName = 'uninitialized';

/// Socket used to write to the universal Zircon logger.
FutureOr<zircon.Socket> _logSocket;

// Enforce limits on number of global tags and length of each tag
List<String> _verifyGlobalTags(List<String> globalTags) {
  List<String> result = <String>[];
  if (globalTags != null) {
    if (globalTags.length > _maxGlobalTags) {
      print('WARNING: Logger initialized with > $_maxGlobalTags tags.');
      print('WARNING: Later tags will be ignored.');
    }
    for (int i = 0; i < _maxGlobalTags && i < globalTags.length; i++) {
      String s = globalTags[i];
      if (s.length > _maxTagLength) {
        print('WARNING: Logger tags limited to $_maxTagLength characters.');
        print('WARNING: Tag "$s" will be truncated.');
        s = s.substring(0, _maxTagLength);
      }
      result.add(s);
    }
  }
  return result;
}

/// LogWriter that outputs to stdout in a similar format the original fuchsia
///  logger.
void writeLogToStdout(LogWriterMessage message) {
  final List<dynamic> scopes = <dynamic>[
    _getLevelString(message.logRecord.level),
  ];
  if (message.scopeName != null) {
    scopes.add(message.scopeName);
  }
  if (message.codeLocation != null) {
    scopes.add(message.codeLocation);
  }
  message.tags.forEach(scopes.add);
  String scopesString = scopes.join(':');
  if (message.logRecord.error != null) {
    print(
        '[$scopesString] ${message.logRecord.message}: ${message.logRecord.error}');
  } else {
    print('[$scopesString] ${message.logRecord.message}');
  }

  if (message.logRecord.stackTrace != null) {
    print('${message.logRecord.stackTrace}');
  }
}

int _convertLogLevel(Level logLevel) =>
    _enumToFuchsiaLevelMap[logLevel] ?? _unexpectedLoggingLevel;

/// Format log message zircon socket connected to Log Viewer
void writeLogToSocket(LogWriterMessage message) {
  ByteData bytes = ByteData(_socketBufferLength)
    ..setUint64(0, pid, Endian.little)
    ..setUint64(8, Isolate.current.hashCode, Endian.little)
    ..setUint64(16, message.logRecord.systemTime, Endian.little)
    ..setInt32(24, _convertLogLevel(message.logRecord.level), Endian.little)
    ..setUint32(28, 0, Endian.little); // TODO droppedLogs
  int byteOffset = 32;

  // Write global tags
  int totalTagCount = 0;
  if (message.scopeName != null) {
    byteOffset = _setTag(bytes, byteOffset, message.scopeName);
    totalTagCount++;
  }
  if (message.codeLocation != null) {
    byteOffset = _setTag(bytes, byteOffset, message.codeLocation);
    totalTagCount++;
  }
  for (String tag in message.tags) {
    if (tag != null && totalTagCount < _maxCombinedTags) {
      byteOffset = _setTag(bytes, byteOffset, tag);
      totalTagCount++;
    }
  }
  // Local tags are currently not supported by dart.
  bytes.setUint8(byteOffset++, 0);

  // Write message
  byteOffset = _setString(bytes, byteOffset, message.logRecord.message,
      _socketBufferLength - byteOffset - 1);
  if (message.logRecord.error != null) {
    byteOffset = _setString(
        bytes, byteOffset, ': ', _socketBufferLength - byteOffset - 1);
    byteOffset = _setString(
        bytes,
        byteOffset,
        message.logRecord.error.toString(),
        _socketBufferLength - byteOffset - 1);
  }
  if (message.logRecord.stackTrace != null) {
    byteOffset = _setString(
        bytes, byteOffset, '\n', _socketBufferLength - byteOffset - 1);
    byteOffset = _setString(
        bytes,
        byteOffset,
        message.logRecord.stackTrace.toString(),
        _socketBufferLength - byteOffset - 1);
  }
  bytes.setUint8(byteOffset++, 0);
  assert(byteOffset <= _socketBufferLength);

  void writeBytes(zircon.Socket sock) {
    sock.write(ByteData.view(bytes.buffer, 0, byteOffset));
  }

  if (_logSocket is Future) {
    // need to wrap in a function to avoid casting errors
    _writeToSocketFuture(_logSocket, writeBytes);
  } else {
    writeBytes(_logSocket);
  }
}

void _writeToSocketFuture(Future<zircon.Socket> socketFuture,
        void Function(zircon.Socket) writer) =>
    socketFuture.then(writer);

// Write a string to ByteData with a leading length byte. Return the byteOffstet
// to use for the next value.
int _setTag(ByteData bytes, int byteOffset, String tag) {
  if (tag == null || tag == 'null') {
    return byteOffset;
  }
  int nextOffset = _setString(bytes, byteOffset + 1, tag, _maxTagLength);
  bytes.setUint8(byteOffset, nextOffset - byteOffset - 1);
  return nextOffset;
}

// Wrie a non-terminated string to ByteData. Return the byteOffset to use for
// the terminating byte or the next value.
int _setString(ByteData bytes, int firstByteOffset, String value, int maxLen) {
  if (value == null || value.isEmpty) {
    return firstByteOffset;
  }
  List<int> charBytes = utf8.encode(value);
  int len = min(charBytes.length, maxLen);
  int byteOffset = firstByteOffset;
  for (int i = 0; i < len; i++) {
    bytes.setUint8(byteOffset++, charBytes[i]);
  }
  // If the string was truncated (and there is space), add an elipsis character.
  if (len < charBytes.length && len >= 3) {
    const int period = 46; // UTF8 value for '.'
    for (int i = 1; i <= 3; i++) {
      bytes.setUint8(byteOffset - i, period);
    }
  }
  return byteOffset;
}

/// A convenient function for displaying the stack trace of the caller in the
/// console.
void showStackTrace() {
  print(Trace.current(1).toString());
}

/// Emits an instant trace with [name] prefixed with [log]'s name
void trace(String name) {
  Timeline.instantSync('$_loggerName $name');
}

/// From the given [Trace], finds the last [Frame] from this package
/// (lib.app.dart) and then the next [Frame] not in this package. That frame
/// represents whomever called the log function and is returned.
/// If no such [Frame] is found, returns `null`.
///
/// SEE: https://github.com/dart-lang/logging/issues/32
Frame _findCallerFrame(Trace trace) {
  bool foundLogging = false;
  Frame matchedFrame;

  for (int i = 0; i < trace.frames.length; ++i) {
    final Frame frame = trace.frames[i];
    final bool loggingPackage = frame.package == 'lib.app.dart';
    if (foundLogging && !loggingPackage) {
      matchedFrame = frame;
    }
    foundLogging = loggingPackage;
  }

  return matchedFrame;
}

/// Remaps the level string to the ones used in FTL.
String _getLevelString(Level level) {
  if (level == null) {
    return null;
  }

  if (level == Level.FINE) {
    return 'VLOG(1)';
  }

  if (level == Level.FINER) {
    return 'VLOG(2)';
  }

  if (level == Level.FINEST) {
    return 'VLOG(3)';
  }

  if (level == Level.SEVERE) {
    return 'ERROR';
  }

  if (level == Level.SHOUT) {
    return 'FATAL';
  }

  return level.toString();
}