Include more standard logging, prepare for release (#73)

CHANGELOG.md

@@ -1,3 +1,15 @@
+## 0.4.3
+
+* When logging, the following `protoPayload` values are now populated:
+  * `instanceId`
+  * `referrer`
+  * `traceId` via the `X-Cloud-Trace-Context` request header.
+
+* The `appengine.googleapis.com/instance_name` label is also populated for 
+  all log entries.
+
+* `traceId` was also added to the `ClientContext` class.
+
 ## 0.4.2
 
 * Add support for connecting to memcache instance defined by environment

lib/src/api_impl/stderr_logging_impl.dart

@@ -13,16 +13,12 @@ import '../logging_impl.dart';
 class StderrRequestLoggingImpl extends LoggingImpl {
   final String _httpMethod;
   final String _httpResource;
-  final String _userAgent;
-  final String _host;
-  final String _ip;
   final DateTime _startTimestamp = new DateTime.now().toUtc();
   final List<_LogLine> _gaeLogLines = <_LogLine>[];
 
   LogLevel _currentLogLevel;
 
-  StderrRequestLoggingImpl(this._httpMethod, this._httpResource,
-      this._userAgent, this._host, this._ip) {
+  StderrRequestLoggingImpl(this._httpMethod, this._httpResource) {
     _resetState();
   }
 

lib/src/appengine_context.dart

@@ -12,11 +12,12 @@ class AppengineContext {
   final String version;
   final String module;
   final String instance;
+  final String instanceId;
   final bool isDevelopmentEnvironment;
   final AssetsManager assets;
 
   AppengineContext(this.isDevelopmentEnvironment, this.applicationID,
-      this.version, this.module, this.instance, Uri pubServeUrl)
+      this.version, this.module, this.instance, this.instanceId, Uri pubServeUrl)
       : partition = '',
         assets = new AssetsManager(pubServeUrl, isDevelopmentEnvironment);
 

lib/src/appengine_internal.dart

@@ -172,8 +172,10 @@ Future<ContextRegistry> _initializeAppEngine() async {
   final Uri pubServeUrl =
       pubServeUrlString != null ? Uri.parse(pubServeUrlString) : null;
 
-  final context = new AppengineContext(
-      isDevEnvironment, projectId, versionId, serviceId, instance, pubServeUrl);
+  final instanceId = await _getInstanceid();
+
+  final context = new AppengineContext(isDevEnvironment, projectId, versionId,
+      serviceId, instance, instanceId, pubServeUrl);
 
   final serviceAccount = _obtainServiceAccountCredentials(gcloudKey);
   final loggerFactory =
@@ -331,7 +333,9 @@ Future<LoggerFactory> _obtainLoggerFactory(AppengineContext context,
         context.applicationID,
         context.module,
         context.version,
-        zoneId);
+        zoneId,
+        context.instance,
+        context.instanceId);
     ss.registerScopeExitCallback(sharedLoggingService.close);
     return new GrpcLoggerFactory(sharedLoggingService);
   }
@@ -394,11 +398,15 @@ auth.ServiceAccountCredentials _obtainServiceAccountCredentials(
   return null;
 }
 
-Future<String> _getZoneInProduction() async {
+Future<String> _getZoneInProduction() => _getMetadataValue('zone');
+
+Future<String> _getInstanceid() => _getMetadataValue('id');
+
+Future<String> _getMetadataValue(String path) async {
   final client = new http.Client();
   try {
     var response = await client.get(
-        'http://metadata.google.internal/computeMetadata/v1/instance/zone',
+        'http://metadata.google.internal/computeMetadata/v1/instance/$path',
         headers: {'Metadata-Flavor': 'Google'});
     if (response.statusCode == HttpStatus.OK) {
       return p.split(response.body).last;
@@ -429,10 +437,16 @@ class GrpcLoggerFactory implements LoggerFactory {
 
   GrpcLoggerFactory(this._shared);
 
-  LoggingImpl newRequestSpecificLogger(String method, String resource,
-      String userAgent, String host, String ip) {
+  LoggingImpl newRequestSpecificLogger(
+      String method,
+      String resource,
+      String userAgent,
+      String host,
+      String ip,
+      String traceId,
+      String referrer) {
     return new grpc_logging_impl.GrpcRequestLoggingImpl(
-        _shared, method, resource, userAgent, host, ip);
+        _shared, method, resource, userAgent, host, ip, traceId, referrer);
   }
 
   logging.Logging newBackgroundLogger() {
@@ -444,10 +458,15 @@ class GrpcLoggerFactory implements LoggerFactory {
 ///
 /// The implementation writes log messages to stderr.
 class StderrLoggerFactory implements LoggerFactory {
-  LoggingImpl newRequestSpecificLogger(String method, String resource,
-      String userAgent, String host, String ip) {
-    return new stderr_logging_impl.StderrRequestLoggingImpl(
-        method, resource, userAgent, host, ip);
+  LoggingImpl newRequestSpecificLogger(
+      String method,
+      String resource,
+      String userAgent,
+      String host,
+      String ip,
+      String traceId,
+      String referrer) {
+    return new stderr_logging_impl.StderrRequestLoggingImpl(method, resource);
   }
 
   logging.Logging newBackgroundLogger() {

lib/src/client_context.dart

@@ -22,6 +22,14 @@ abstract class ClientContext {
 
   Services get services;
   Assets get assets;
+
+  /// The `TRACE_ID` value from the `X-Cloud-Trace-Context` request header.
+  ///
+  /// If `X-Cloud-Trace-Context` was not included in the request, the value will
+  /// be `null`.
+  ///
+  /// See https://cloud.google.com/trace/docs/support for details.
+  String get traceId;
 }
 
 class Services {

lib/src/grpc_api_impl/logging_impl.dart

@@ -39,17 +39,27 @@ class GrpcRequestLoggingImpl extends LoggingImpl {
   final String _userAgent;
   final String _host;
   final String _ip;
+  final String _traceId;
+  final String _referrer;
   final int _startTimestamp;
   final List<gae_log.LogLine> _gaeLogLines = <gae_log.LogLine>[];
 
   api.LogSeverity _currentSeverity;
   int _estimatedSize;
   bool _isFirst;
 
-  GrpcRequestLoggingImpl(this._sharedLoggingService, this._httpMethod,
-      this._httpResource, this._userAgent, this._host, this._ip)
+  GrpcRequestLoggingImpl(
+      this._sharedLoggingService,
+      this._httpMethod,
+      this._httpResource,
+      this._userAgent,
+      this._host,
+      this._ip,
+      this._traceId,
+      this._referrer)
       : _startTimestamp = new DateTime.now().toUtc().millisecondsSinceEpoch {
     _resetState();
+    _isFirst = true;
   }
 
   void log(LogLevel level, String message, {DateTime timestamp}) {
@@ -126,7 +136,16 @@ class GrpcRequestLoggingImpl extends LoggingImpl {
       ..ip = _ip
       ..line.addAll(_gaeLogLines)
       ..first = _isFirst
-      ..finished = finish;
+      ..finished = finish
+      ..instanceId = _sharedLoggingService.instanceId;
+
+    if (_traceId != null) {
+      appengineRequestLog.traceId = _traceId;
+    }
+
+    if (_referrer != null) {
+      appengineRequestLog.referrer = _referrer;
+    }
 
     final protoPayload = new api.Any()
       ..typeUrl = 'type.googleapis.com/google.appengine.logging.v1.RequestLog';
@@ -163,6 +182,7 @@ class GrpcRequestLoggingImpl extends LoggingImpl {
 
       logEntry..httpRequest = httpRequest;
     }
+
     protoPayload..value = appengineRequestLog.writeToBuffer();
 
     _sharedLoggingService.enqueue(logEntry);
@@ -215,6 +235,8 @@ class SharedLoggingService {
   final api.LoggingServiceV2Api _clientStub;
   final String projectId;
   final String versionId;
+  final String instanceId;
+  final String _instanceName;
   final List<api.MonitoredResource_LabelsEntry> resourceLabels;
   final String requestLogName;
   final String backgroundLogName;
@@ -226,7 +248,7 @@ class SharedLoggingService {
   int _outstandingRequests = 0;
 
   SharedLoggingService(grpc.Client client, String projectId, String serviceId,
-      String versionId, String zoneId)
+      String versionId, String zoneId, this._instanceName, this.instanceId)
       : _clientStub = new api.LoggingServiceV2Api(
             new grpc.Channel('google.logging.v2', client)),
         projectId = projectId,
@@ -249,6 +271,8 @@ class SharedLoggingService {
   }
 
   void enqueue(api.LogEntry entry) {
+    _addLabel(entry, 'appengine.googleapis.com/instance_name', _instanceName);
+
     _entries.add(entry);
 
     // If all entries have maximum size we should send them once we have 25 in
@@ -309,6 +333,13 @@ class SharedLoggingService {
   }
 }
 
+void _addLabel(api.LogEntry entry, String key, String value) {
+  entry
+    ..labels.add(new api.LogEntry_LabelsEntry()
+      ..key = key
+      ..value = value);
+}
+
 api.Timestamp _protobufTimestampFromMilliseconds(int ms) {
   return new api.Timestamp()
     ..seconds = new api.Int64(ms ~/ 1000)

lib/src/server/context_registry.dart

@@ -20,7 +20,13 @@ import '../logging_impl.dart';
 
 abstract class LoggerFactory {
   LoggingImpl newRequestSpecificLogger(
-      String method, String resource, String userAgent, String host, String ip);
+      String method,
+      String resource,
+      String userAgent,
+      String host,
+      String ip,
+      String traceId,
+      String referrer);
   Logging newBackgroundLogger();
 }
 
@@ -41,10 +47,17 @@ class ContextRegistry {
   }
 
   ClientContext add(HttpRequest request) {
-    final services = _getServices(request);
+    String traceId;
+    // See https://cloud.google.com/trace/docs/support
+    final traceHeader = request.headers.value('X-Cloud-Trace-Context');
+    if (traceHeader != null) {
+      traceId = traceHeader.split('/')[0];
+    }
+
+    final services = _getServices(request, traceId);
     final assets = new AssetsImpl(request, _appengineContext);
     final context = new _ClientContextImpl(
-        services, assets, _appengineContext.isDevelopmentEnvironment);
+        services, assets, _appengineContext.isDevelopmentEnvironment, traceId);
     _request2context[request] = context;
 
     request.response.done.whenComplete(() {
@@ -65,9 +78,9 @@ class ContextRegistry {
     return new Future.value();
   }
 
-  Services newBackgroundServices() => _getServices(null);
+  Services newBackgroundServices() => _getServices(null, null);
 
-  Services _getServices(HttpRequest request) {
+  Services _getServices(HttpRequest request, String traceId) {
     Logging loggingService;
     if (request != null) {
       final uri = request.requestedUri;
@@ -89,7 +102,13 @@ class ContextRegistry {
       }
 
       loggingService = _loggingFactory.newRequestSpecificLogger(
-          request.method, resource, userAgent, uri.host, ip);
+          request.method,
+          resource,
+          userAgent,
+          uri.host,
+          ip,
+          traceId,
+          request.headers.value(HttpHeaders.REFERER));
     } else {
       loggingService = _loggingFactory.newBackgroundLogger();
     }
@@ -101,11 +120,11 @@ class ContextRegistry {
 class _ClientContextImpl implements ClientContext {
   final Services services;
   final Assets assets;
-  final bool _isDevelopmentEnvironment;
+  final bool isDevelopmentEnvironment;
+  final String traceId;
 
   _ClientContextImpl(
-      this.services, this.assets, this._isDevelopmentEnvironment);
+      this.services, this.assets, this.isDevelopmentEnvironment, this.traceId);
 
-  bool get isDevelopmentEnvironment => _isDevelopmentEnvironment;
-  bool get isProductionEnvironment => !_isDevelopmentEnvironment;
+  bool get isProductionEnvironment => !isDevelopmentEnvironment;
 }

lib/src/server/logging_package_adaptor.dart

@@ -24,7 +24,7 @@ final Map<Level, LogLevel> _loggingLevel2AppengineLoggingLevel = {
 void setupAppEngineLogging() {
   Logger.root.onRecord.listen((LogRecord record) {
     record.zone.run(() {
-      var logging;
+      Logging logging;
       try {
         logging = loggingService;
       } on StateError {

pubspec.yaml

@@ -1,5 +1,5 @@
 name: appengine
-version: 0.4.2
+version: 0.4.3
 author: Dart Team <[email protected]>
 description: Support for using Dart as a custom runtime on Google App Engine Flexible Environment
 homepage: https://github.com/dart-lang/appengine

test/assets_test.dart

@@ -66,22 +66,22 @@ void main() {
     var context;
 
     context = new AppengineContext(
-        true,  null,  null,  null,  null, uri);
+        true,  null,  null,  null,  null, null, uri);
     expect(context.isDevelopmentEnvironment, isTrue);
     expect(context.assets.usePubServe, isTrue);
 
     context = new AppengineContext(
-        false,  null,  null,  null,  null, uri);
+        false,  null,  null,  null,  null, null, uri);
     expect(context.isDevelopmentEnvironment, isFalse);
     expect(context.assets.usePubServe, isFalse);
 
     context = new AppengineContext(
-        true,  null,  null,  null,  null, null);
+        true,  null,  null,  null,  null, null, null);
     expect(context.isDevelopmentEnvironment, isTrue);
     expect(context.assets.usePubServe, isFalse);
 
     context = new AppengineContext(
-        false,  null,  null,  null,  null, null);
+        false,  null,  null,  null,  null, null, null);
     expect(context.isDevelopmentEnvironment, isFalse);
     expect(context.assets.usePubServe, isFalse);
   });
@@ -117,7 +117,7 @@ void main() {
       assert(appServer == null);
       return HttpServer.bind('127.0.0.1', 0).then((server) {
         var appengineContext = new AppengineContext(
-            true,  null,  null,  null,  null, pubServeUri);
+            true,  null,  null,  null,  null, null, pubServeUri);
         appServer = server;
         appServerPort = server.port;
         server.listen((request) {
@@ -229,7 +229,7 @@ void main() {
       assert(appServer == null);
       return HttpServer.bind('127.0.0.1', 0).then((server) {
         var appengineContext = new AppengineContext(
-            true,  null,  null,  null,  null, null);
+            true,  null,  null,  null,  null, null, null);
         appServer = server;
         appServerPort = server.port;
         server.listen((request) {