Simplify logging interface & add RPC method #121

ben-clayton · 2017-03-20T19:10:06Z

Instead of log.Context, now use context.Context.

To log something use:

log.I(ctx, "cat says %v", "meow")
log.W(ctx, "dog says %v", "woof")
log.E(ctx, "fox says %v", "???")

Values are added to the context with:

ctx := log.V{"key": value}.Bind(ctx)

GAPII and GAPIR log messages are parsed into the structured form so they can be filtered.

New streaming RPC GetLogStream() monitors all log messages from GAPIS and all subprocesses interleaved. Can be used by GAPIC to display all logs across all processes.

ben-clayton · 2017-03-20T19:16:30Z

cmd/gapit/trace.go

+			AddPathStart("VK_DEVICE_LAYERS", "VkGraphicsSpy").
+			AddPathStart("VK_LAYER_PATH", libVkLayerGraphicsSpy.Parent().System()).
+			Set("LD_PRELOAD", libgapii.System()),
+	})


It's related. There's new logic to handle stdout and stderr, which adds more options to the start function. Given the number of parameters we're passing in, I opted for a struct.

Yes, I noticed that later. Sorry, I didn't realize it sends out comments right away. Is there no draft comment mode like Critique/Gerrit?

Yes. Next to the single line comment button there should be a "Start Review" green button.

ben-clayton · 2017-03-21T16:11:43Z

Now also contains GAPIC changes to display the merged logs across GAPIC, GAPIS and GAPIR.

ben-clayton · 2017-03-21T17:31:57Z

I'm following up with a final CL that avoids the tree.removeAll()

pmuetschard

FYI: i've checked in a .settings folder which enables a lot of warnings in Eclipse.

pmuetschard · 2017-03-21T17:27:17Z

gapic/src/main/com/google/gapid/views/LogView.java

    dirty.set(false);
  }

+  private String formatTime(Timestamp time) {


Can be static

pmuetschard · 2017-03-21T17:28:31Z

gapic/src/main/com/google/gapid/views/LogView.java

+      case Fatal:
+        return theme.fatalBackground();
+    }
+    return theme.infoBackground();


Please move this into a default case to make the behavior more explicit.

pmuetschard · 2017-03-21T17:28:35Z

gapic/src/main/com/google/gapid/views/LogView.java

+      case Fatal:
+        return theme.fatalForeground();
+    }
+    return theme.infoForeground();


Please move this into a default case to make the behavior more explicit.

pmuetschard · 2017-03-21T17:31:23Z

gapic/src/main/com/google/gapid/views/LogView.java

+  private Color severityBackgroundColor(Log.Severity severity) {
+    switch (severity) {
+      case Verbose:
+        return theme.verboseBackground();


nit: since the case statements are so simple, I'd prefer them to be on one line:

case Verbose: return theme.verboseBackground(); case Debug: return theme.debugBackground(); ...

pmuetschard · 2017-03-21T17:31:50Z

gapic/src/main/com/google/gapid/util/Logging.java

@@ -15,54 +15,64 @@
 */
 package com.google.gapid.util;

+import com.google.gapid.proto.log.Log;
+import com.google.gapid.rpclib.schema.Method;


not actually needed

pmuetschard · 2017-03-21T17:35:20Z

gapic/src/main/com/google/gapid/util/Logging.java

+
+    static LogLevel fromLevel(Level level) {
+      for (LogLevel logLevel : LogLevel.values()) {
+        if (logLevel.level == level) {


This should be range based as it was before.
java.util.logging.Level is not an enum, so you also should not use '==', but .equals.

pmuetschard · 2017-03-21T17:37:14Z

gapic/src/main/com/google/gapid/util/Logging.java

+  }
+
+  /**
+   * Adds a {@link Log.Message} to the buffer, bypassing the Java {@link LogManager}.


Unfortunately this needs to be {@link com.google.gapid.proto.log.Log.Message}

Is this Eclipse telling you this? IntelliJ seems fine with it as-is.

Yes and no. Eclipse does give me the warning, but it comes straight from javadoc:
src/main/com/google/gapid/util/Logging.java:145: warning - Tag @link: reference not found: Log.Message

pmuetschard · 2017-03-21T17:38:26Z

gapic/src/main/com/google/gapid/util/Logging.java

+  private static final String GAPID_PREFIX = "com.google.gapid.";
+  private static final String GOOG_PREFIX = "com.google.";
+
+  private static String shorten(String className) {


make this protected, as you are using it from multiple inner classes

I'm sure I've asked this before, but why is this an issue?
Done anyway.

The JVM has no concept (almost) of inner classes. To the JVM, an inner class and its container outer class are simply two different classes. You cannot call private methods of another class. The compiler adds synthetic methods to make it look like you can call private methods from inner/outer classes. These synthetic methods add unnecessary overhead and pollute stack traces. If you're going to allow access via these synthetic methods, why not give access directly?

pmuetschard · 2017-03-21T17:40:15Z

gapic/src/main/com/google/gapid/util/Logging.java

    public Runnable listener;
-    private final StringBuilder buffer = new StringBuilder();
+    private final LinkedList<Log.Message> buffer = new LinkedList<>();


buffer is shadowing Logging.buffer. I suggest renaming Logging.buffer to Logging.messageBuffer

Changed in later CL.

pmuetschard · 2017-03-21T17:44:02Z

gapic/src/main/com/google/gapid/server/GapitPkgInfoProcess.java

-      byte[] data = ByteStreams.toByteArray(in);
+      SearchingInputStream is = new SearchingInputStream(in);
+      if (!is.search(PACKAGE_DATA_MARKER.getBytes())) {
+        throw new RuntimeException("The gapit command didn't produce the data marker.");


Resource leak: 'is' is not closed at this location.

I'd suggest making the search method static and avoid the wrapping in another input stream. The SearchingInputStream class has no additional state, so it's not needed.

The SearchingInputStream class has no additional state, so it's not needed.

Well, it has the buffered reader state. I've wrapped it with a try-with-resources,

ben-clayton · 2017-03-21T18:39:18Z

FYI: i've checked in a .settings folder which enables a lot of warnings in Eclipse.

Thanks, but I use IntelliJ. :)

pmuetschard · 2017-03-21T18:47:08Z

gapic/src/main/com/google/gapid/util/Logging.java

-import java.util.logging.Logger;
-import java.util.logging.StreamHandler;
+import java.util.LinkedList;
+import java.util.logging.*;


Please no * imports. I've been following the Google style for Java, and I'd like to continue to do so.

Done. Another IntelliJ default that I continually battle.

pmuetschard · 2017-03-21T18:48:14Z

gapic/src/main/com/google/gapid/util/Logging.java


 /**
 * Logging setup and utilities.
 */
 public class Logging {
  /**
-   * Possible log level flag values.
+   * Possible logMessage level flag values.


Search replace?

Refactor gone crazy. Fixed.

pmuetschard · 2017-03-21T18:51:23Z

gapic/src/main/com/google/gapid/util/Logging.java

  }

  public static final Flag<LogLevel> logLevel = Flags.value(
      "logLevel", LogLevel.INFO, "Logging level [OFF, ERROR, WARNING, INFO, DEBUG, ALL].");
  public static final Flag<String> logDir = Flags.value(
-      "logDir", System.getProperty("java.io.tmpdir"), "Directory for log files.");
+      "logDir", System.getProperty("java.io.tmpdir"), "Directory for logMessage files.");


Search replace?

pmuetschard · 2017-03-21T18:51:47Z

gapic/src/main/com/google/gapid/util/Logging.java

@@ -83,7 +93,7 @@ public static void init() {

    if (!logDir.get().isEmpty()) {
      try {
-        FileHandler fileHandler = new FileHandler(logDir.get() + File.separator + "gapic.log");
+        FileHandler fileHandler = new FileHandler(logDir.get() + File.separator + "gapic.logMessage");


Search replace?

pmuetschard · 2017-03-21T19:07:51Z

gapic/src/main/com/google/gapid/util/Logging.java

+  }
+
+  /**
+   * Adds a {@link Log.Message} to the buffer, bypassing the Java {@link LogManager}.


Yes and no. Eclipse does give me the warning, but it comes straight from javadoc:
src/main/com/google/gapid/util/Logging.java:145: warning - Tag @link: reference not found: Log.Message

pmuetschard · 2017-03-21T19:27:47Z

gapic/src/main/com/google/gapid/util/Logging.java

  }

-  public static void setListener(Runnable listener) {
-    buffer.listener = (listener == null) ? () -> { /* empty */ } : listener;
+  public static void setListener(Listener listener_) {


Name shadowing is acceptable on setters, if you're shadowing the variable you're setting.

If you don't like to do that, please use new instead of _.

pmuetschard · 2017-03-21T19:32:23Z

gapic/src/main/com/google/gapid/util/Logging.java

@@ -123,6 +135,7 @@ public static void setListener(Runnable listener) {
   */
  public static void logMessage(Log.Message message) {


This is now very much round-about: Buffer.publish calls Logging.logMessage, which calls Buffer.add and then fires the event.

Better to keep it they way it was:
logMessage and Buffer.publish call Buffer.add
Buffer.add fires the event

I've separated Buffer and Handler. The inner class was doing too much - hence the extraction of the event logic. Hopefully this is now cleaner and would be nice and simple to make the classes public if needed in the future.

pmuetschard · 2017-03-21T19:33:12Z

gapic/src/main/com/google/gapid/util/Logging.java

+   * new messages.
+   */
+  private static class MessageIterator implements Iterator<Log.Message> {
+    private final Buffer buffer;


Shadows Logging.buffer.

Given that the class is static, does it?

Yes, because so is Logging.buffer.

Fair point.

pmuetschard · 2017-03-21T19:38:29Z

gapic/src/main/com/google/gapid/util/Logging.java

+      if (thrown != null) {
+        for (StackTraceElement el : thrown.getStackTrace()) {
+          builder.addCallstack(Log.SourceLocation.newBuilder()
+              .setFile(el.getFileName())


el.getFileName can return null (protos don't like nulls).

pmuetschard · 2017-03-21T19:44:09Z

gapic/src/main/com/google/gapid/server/GapisConnection.java

+        Service.GetLogStreamRequest request = Service.GetLogStreamRequest.newBuilder().build();
+        Iterator<Log.Message> it = GapidGrpc.newBlockingStub(channel).getLogStream(request);
+        while (it.hasNext()) {
+          monitor.onLogMessage(it.next());


This now causes an exception on clean shutdown. Before closing the connection to gapis, the logger thread should be stopped.

I think you'd be better off using a StreamObserver and the async case rather than the blocking case with an extra thread.

AFAICT, streamed RPCs aren't exposed in the FutureStub (if that's what you're referring to).

Now unbinds the LogMonitor on close(). Added warning for unexpected StatusRuntimeExceptions that are thrown by the thread.

Replace all uses of log.Context with context.Context. Squash the functionality of jot, memo, severity, fault into log.

Change-Id: I39df2ad33a3f780216fcbcbdcecbfd905252796e

Change-Id: I8ca1d2b11143352dfb6b8802f17c128d5dc49ee8

Change-Id: I4532f987e77b84b976a4d10adce39b75f1ce6d8e

Turn them into log.Messages. Change-Id: I95153e2a860c6db46e9a78ebc047599685239b0c

Let's you control them on the command line. Change-Id: Ib8b12a830a5a22b9f8c1c2fe2cbe00b7a451f1b0

Change-Id: I486fb73fed83100734fcb21d2bf391d44a862d51

Fixes the package picker when also logging to stdout.

Change-Id: Ic64e73cdf4d9b913594c7d02242c9c5dd06e1980

Change-Id: Ice567770dd74c9b2093c732f80be001a6e9d23c7

Change-Id: Ib103d8f824a7e0d7226584ad73127ad291dc763d

dsrbecky · 2017-03-22T13:39:45Z

core/log/severity.go

-func (ctx logContext) Alert() Logger {
-	return ctx.At(severity.Alert)
+func (s Severity) String() string {
+	switch s {


Handle Verbose...

dsrbecky · 2017-03-22T13:40:00Z

core/log/severity.go

-	return ctx.At(severity.Critical)
+// Short returns the severity string with a single character.
+func (s Severity) Short() string {
+	switch s {


Handle Verbose...

Change-Id: I15a47ec97283efdce403b87af8491295ee9c15f9

dsrbecky · 2017-03-22T13:52:13Z

+1

Change-Id: If1619af5063c4e98268a8f0dcf33678970b251dd

Change-Id: I428d36fd26c984a7ffcadc50eeb948378d7b935a

pmuetschard · 2017-03-22T17:12:00Z

gapic/src/main/com/google/gapid/server/GapisConnection.java

 import io.grpc.okhttp.OkHttpChannelProvider;

 /**
 * A connection to a running Graphics API Server (GAPIS).
 */
 public abstract class GapisConnection implements Closeable {
+  private static final Logger LOG = Logger.getLogger(Client.class.getName());


Client.class -> GapisConnection.class

pmuetschard · 2017-03-22T17:14:13Z

gapic/src/main/com/google/gapid/server/GapitPkgInfoProcess.java

@@ -23,7 +23,8 @@
 import com.google.gapid.proto.pkginfo.PkgInfo;
 import com.google.gapid.proto.pkginfo.PkgInfo.PackageList;

-import java.io.File;
+import java.io.*;


Another .* import.

I think you can tell intellij not to do this by setting the minimum number of classes needed before it collapses imports to some very high number.

pmuetschard · 2017-03-22T17:18:05Z

gapic/src/main/com/google/gapid/util/Logging.java

+
+  private static final RingBuffer buffer = new RingBuffer(BUFFER_SIZE);
+
+  private static final Handler handler = new Handler() {{


You no longer need to hang on to this reference, so just create the handler in the init() method and add it to the root logger.

pmuetschard · 2017-03-22T17:18:48Z

gapic/src/main/com/google/gapid/util/Logging.java

+   * {@link Handler} that handles {@link LogRecord}s converting them to
+   * {@link com.google.gapid.proto.log.Log.Message}s and then broadcasting them to listeners.
+   */
+  protected static class Handler extends java.util.logging.Handler {


Maybe name this class ProtoHandler, or ProtoConverter?

They both sound like the Proto is the source when it's the target. Opted for LogToMessageHandler.

pmuetschard · 2017-03-22T17:20:59Z

gapic/src/main/com/google/gapid/views/LogView.java

+      }
+      Log.Severity severity = message.getSeverity();
+      TreeItem item = newItem(tree, severity);
+      String[] lines = message.getText().split("(\n)|(\r\n)");


split("\r?\n")

Change-Id: I1f8ac3259cf5b528feedf0a2077c4d966f53e375

- Add drag-selection to the Process Panel. - Change CPU slices' color after drag-selecting in Thread Panel. - Bug: http://b/147922469. #2 and #3.

ben-clayton added the GAPIS label Mar 20, 2017

ben-clayton requested review from dsrbecky, ianthehat, AWoloszyn and pmuetschard March 20, 2017 19:10

ben-clayton commented Mar 20, 2017

View reviewed changes

pmuetschard requested changes Mar 21, 2017

View reviewed changes

ben-clayton and others added 18 commits March 22, 2017 13:27

Implement a simpler logging interface.

7e5c64d

Replace all uses of log.Context with context.Context. Squash the functionality of jot, memo, severity, fault into log.

Add log streaming RPC.

12af1f1

Change-Id: I39df2ad33a3f780216fcbcbdcecbfd905252796e

core/app: Bind the exe name as the log process field.

a5bc0a6

Change-Id: I8ca1d2b11143352dfb6b8802f17c128d5dc49ee8

core/log: Add verbose severity.

49a1916

Change-Id: I4532f987e77b84b976a4d10adce39b75f1ce6d8e

gapir/client: Parse log message from gapir

7d7ed0f

Turn them into log.Messages. Change-Id: I95153e2a860c6db46e9a78ebc047599685239b0c

core/log: Add style names

d741198

Let's you control them on the command line. Change-Id: Ib8b12a830a5a22b9f8c1c2fe2cbe00b7a451f1b0

core/text/note: Remove the now unused package

a71b4d2

Change-Id: I486fb73fed83100734fcb21d2bf391d44a862d51

gapic: Merge logs from GAPIS, GAPIR and GAPIC.

0042fe0

gapit: Prefix the protodata with a header

a93d16f

Fixes the package picker when also logging to stdout.

gapic: Don't clear the log with each new message.

5728cc1

Address code review comments

f707ba1

Reglob

2a3e51c

Remove proto that got moved to a subdirectoy

51fa2ae

Make formatTime static.

3ccf954

Reduce some of the GAPIR spam to DEBUG level.

170092f

Address more review comments.

c0a7a28

Change-Id: Ic64e73cdf4d9b913594c7d02242c9c5dd06e1980

gapir: Adjust logs to be less spammy

e3456e1

Change-Id: Ice567770dd74c9b2093c732f80be001a6e9d23c7

Fixes for new changes landed in master

992634e

Change-Id: Ib103d8f824a7e0d7226584ad73127ad291dc763d

ben-clayton force-pushed the logs branch from df5e8ac to 992634e Compare March 22, 2017 13:33

dsrbecky reviewed Mar 22, 2017

View reviewed changes

core/log: Handle verbose severity

e4b785a

Change-Id: I15a47ec97283efdce403b87af8491295ee9c15f9

ben-clayton added 2 commits March 22, 2017 13:54

Fix javadoc link

7133d5d

Change-Id: If1619af5063c4e98268a8f0dcf33678970b251dd

Merge 'github/master' into logs

a422b22

Change-Id: I428d36fd26c984a7ffcadc50eeb948378d7b935a

pmuetschard reviewed Mar 22, 2017

View reviewed changes

Address more review comments.

472c787

Change-Id: I1f8ac3259cf5b528feedf0a2077c4d966f53e375

pmuetschard approved these changes Mar 22, 2017

View reviewed changes

Merge branch master into logs

67521a6

ben-clayton merged commit 4b31e32 into google:master Mar 22, 2017

ben-clayton deleted the logs branch March 22, 2017 19:33

pmuetschard pushed a commit that referenced this pull request Jun 11, 2020

Fix two bugs related to drag selection. (#121)

12c4505

- Add drag-selection to the Process Panel. - Change CPU slices' color after drag-selecting in Thread Panel. - Bug: http://b/147922469. #2 and #3.

		@@ -123,6 +135,7 @@ public static void setListener(Runnable listener) {
		*/
		public static void logMessage(Log.Message message) {


		private static final RingBuffer buffer = new RingBuffer(BUFFER_SIZE);

		private static final Handler handler = new Handler() {{

Simplify logging interface & add RPC method #121

Simplify logging interface & add RPC method #121

Conversation

ben-clayton commented Mar 20, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ben-clayton commented Mar 21, 2017

ben-clayton commented Mar 21, 2017

pmuetschard left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ben-clayton commented Mar 21, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dsrbecky commented Mar 22, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ben-clayton commented Mar 20, 2017 •

edited

Loading