common/org.eclipse.tracecompass.common.core.tests/src/org/eclipse/tracecompass/common/core/tests/log/LoggerTest.java

   1 /*******************************************************************************
   2  * Copyright (c) 2017 Ericsson
   3  *
   4  * All rights reserved. This program and the accompanying materials are
   5  * made available under the terms of the Eclipse Public License v1.0 which
   6  * accompanies this distribution, and is available at
   7  * http://www.eclipse.org/legal/epl-v10.html
   8  *******************************************************************************/
   9
  10 package org.eclipse.tracecompass.common.core.tests.log;
  11
  12 import static org.junit.Assert.assertEquals;
  13 import static org.junit.Assert.assertNotNull;
  14
  15 import java.io.IOException;
  16 import java.io.OutputStream;
  17 import java.util.ArrayList;
  18 import java.util.List;
  19 import java.util.logging.Level;
  20 import java.util.logging.Logger;
  21 import java.util.logging.SimpleFormatter;
  22 import java.util.logging.StreamHandler;
  23
  24 import org.eclipse.jdt.annotation.NonNull;
  25 import org.eclipse.tracecompass.common.core.log.TraceCompassLogUtils;
  26 import org.eclipse.tracecompass.common.core.log.TraceCompassLogUtils.FlowScopeLog;
  27 import org.eclipse.tracecompass.common.core.log.TraceCompassLogUtils.FlowScopeLogBuilder;
  28 import org.junit.Before;
  29 import org.junit.Test;
  30
  31 /**
  32  * Test cases for logger (line sensitive!)
  33  *
  34  * @author Matthew Khouzam
  35  */
  36 public class LoggerTest {
  37
  38     private StringOutputStream fLog;
  39     private Logger fLogger;
  40     private StreamHandler fStreamHandler;
  41
  42     private static String eventWithNoTs(String event) {
  43         return event.replaceFirst("\\\"ts\\\"\\:\\d+", "\"ts\":0");
  44     }
  45
  46     private static String eventUnifyId(String event) {
  47         return event.replaceFirst("\\\"id\\\"\\:\\\"0x[0-9A-Fa-f]+\\\"", "\"id\":\"0x1234\"");
  48     }
  49
  50     private static class StringOutputStream extends OutputStream {
  51
  52         private List<String> fMessages = new ArrayList<>();
  53         private StringBuilder sb = new StringBuilder();
  54         private boolean secondLine = false;
  55         private boolean start = true;
  56
  57         @Override
  58         public void write(int b) throws IOException {
  59             // We don't care about carriage return (Windows). We only need to
  60             // rely on \n to detect the next line
  61             if (b == '\r') {
  62                 return;
  63             }
  64
  65             if (b != '\n') {
  66                 if (secondLine) {
  67                     if (start) {
  68                         sb.append((char) b);
  69                     }
  70                     if (b == ',') {
  71                         start = true;
  72                     }
  73                 }
  74             } else {
  75                 if (secondLine) {
  76                     fMessages.add(eventUnifyId(eventWithNoTs(sb.toString())));
  77                     sb = new StringBuilder();
  78                     secondLine = false;
  79                 } else {
  80                     secondLine = true;
  81                 }
  82             }
  83         }
  84
  85         public List<String> getMessages() {
  86             return fMessages;
  87         }
  88     }
  89
  90     /**
  91      * Set up logger
  92      */
  93     @Before
  94     public void before() {
  95         fLogger = Logger.getAnonymousLogger();
  96         fLog = new StringOutputStream();
  97         fStreamHandler = new StreamHandler(fLog, new SimpleFormatter());
  98         fStreamHandler.setLevel(Level.FINER);
  99         fLogger.setLevel(Level.ALL);
 100         fLogger.addHandler(fStreamHandler);
 101     }
 102
 103     /**
 104      * Test simple logging
 105      */
 106     @Test
 107     public void testHelloWorld() {
 108         Logger logger = fLogger;
 109         assertNotNull(logger);
 110         try (TraceCompassLogUtils.ScopeLog log = new TraceCompassLogUtils.ScopeLog(logger, Level.INFO, "world")) {
 111             // do something
 112             new Object();
 113         }
 114         fStreamHandler.flush();
 115         assertEquals("INFO: {\"ts\":0,\"ph\":\"B\",\"tid\":1,\"name\":\"world\"}", fLog.getMessages().get(0));
 116         assertEquals("INFO: {\"ts\":0,\"ph\":\"E\",\"tid\":1}", fLog.getMessages().get(1));
 117     }
 118
 119     /**
 120      * Test nesting
 121      */
 122     @Test
 123     public void testNesting() {
 124         Logger logger = fLogger;
 125         assertNotNull(logger);
 126         try (TraceCompassLogUtils.ScopeLog log = new TraceCompassLogUtils.ScopeLog(logger, Level.INFO, "foo")) {
 127             // do something
 128             new Object();
 129             try (TraceCompassLogUtils.ScopeLog log1 = new TraceCompassLogUtils.ScopeLog(logger, Level.INFO, "bar")) {
 130                 // do something
 131                 new Object();
 132             }
 133         }
 134         fStreamHandler.flush();
 135         assertEquals("INFO: {\"ts\":0,\"ph\":\"B\",\"tid\":1,\"name\":\"foo\"}", fLog.getMessages().get(0));
 136         assertEquals("INFO: {\"ts\":0,\"ph\":\"B\",\"tid\":1,\"name\":\"bar\"}", fLog.getMessages().get(1));
 137         assertEquals("INFO: {\"ts\":0,\"ph\":\"E\",\"tid\":1}", fLog.getMessages().get(2));
 138         assertEquals("INFO: {\"ts\":0,\"ph\":\"E\",\"tid\":1}", fLog.getMessages().get(3));
 139     }
 140
 141     /**
 142      * Test nesting with filtering
 143      */
 144     @Test
 145     public void testNestingFiltered() {
 146         Logger logger = fLogger;
 147         assertNotNull(logger);
 148         try (TraceCompassLogUtils.ScopeLog log = new TraceCompassLogUtils.ScopeLog(logger, Level.FINE, "foo")) {
 149             // do something
 150             new Object();
 151             try (TraceCompassLogUtils.ScopeLog log1 = new TraceCompassLogUtils.ScopeLog(logger, Level.FINER, "bar")) {
 152                 // do something
 153                 new Object();
 154                 try (TraceCompassLogUtils.ScopeLog log2 = new TraceCompassLogUtils.ScopeLog(logger, Level.FINEST, "baz")) {
 155                     // do something
 156                     new Object();
 157                 }
 158             }
 159         }
 160         fStreamHandler.flush();
 161         assertEquals("FINE: {\"ts\":0,\"ph\":\"B\",\"tid\":1,\"name\":\"foo\"}", fLog.getMessages().get(0));
 162         assertEquals("FINER: {\"ts\":0,\"ph\":\"B\",\"tid\":1,\"name\":\"bar\"}", fLog.getMessages().get(1));
 163         assertEquals("FINER: {\"ts\":0,\"ph\":\"E\",\"tid\":1}", fLog.getMessages().get(2));
 164         assertEquals("FINE: {\"ts\":0,\"ph\":\"E\",\"tid\":1}", fLog.getMessages().get(3));
 165     }
 166
 167     /**
 168      * Test nesting with different loglevels
 169      */
 170     @Test
 171     public void testNestingLogLevels() {
 172         Logger logger = fLogger;
 173         assertNotNull(logger);
 174         try (TraceCompassLogUtils.ScopeLog log = new TraceCompassLogUtils.ScopeLog(logger, Level.WARNING, "foo")) {
 175             try (TraceCompassLogUtils.ScopeLog log1 = new TraceCompassLogUtils.ScopeLog(logger, Level.FINE, "bar")) {
 176                 // do something
 177                 new Object();
 178             }
 179         }
 180         fStreamHandler.flush();
 181         assertEquals("WARNING: {\"ts\":0,\"ph\":\"B\",\"tid\":1,\"name\":\"foo\"}",
 182                 fLog.getMessages().get(0));
 183         assertEquals("FINE: {\"ts\":0,\"ph\":\"B\",\"tid\":1,\"name\":\"bar\"}", fLog.getMessages().get(1));
 184         assertEquals("FINE: {\"ts\":0,\"ph\":\"E\",\"tid\":1}", fLog.getMessages().get(2));
 185         assertEquals("WARNING: {\"ts\":0,\"ph\":\"E\",\"tid\":1}", fLog.getMessages().get(3));
 186     }
 187
 188     /**
 189      * Test nesting with additional data
 190      */
 191     @Test
 192     public void testNestingWithData() {
 193         Logger logger = fLogger;
 194         assertNotNull(logger);
 195         try (TraceCompassLogUtils.ScopeLog log = new TraceCompassLogUtils.ScopeLog(logger, Level.WARNING, "foo")) {
 196             try (TraceCompassLogUtils.ScopeLog log1 = new TraceCompassLogUtils.ScopeLog(logger, Level.FINE, "bar")) {
 197                 // do something
 198                 log1.addData("return", false);
 199             }
 200         }
 201         fStreamHandler.flush();
 202         assertEquals("WARNING: {\"ts\":0,\"ph\":\"B\",\"tid\":1,\"name\":\"foo\"}",
 203                 fLog.getMessages().get(0));
 204         assertEquals("FINE: {\"ts\":0,\"ph\":\"B\",\"tid\":1,\"name\":\"bar\"}", fLog.getMessages().get(1));
 205         assertEquals("FINE: {\"ts\":0,\"ph\":\"E\",\"tid\":1,\"args\":{\"return\":\"false\"}}", fLog.getMessages().get(2));
 206         assertEquals("WARNING: {\"ts\":0,\"ph\":\"E\",\"tid\":1}", fLog.getMessages().get(3));
 207     }
 208
 209     /**
 210      * Test flow with filtering
 211      */
 212     @Test
 213     public void testFlowFiltered() {
 214         Logger logger = fLogger;
 215         assertNotNull(logger);
 216         try (FlowScopeLog log = new FlowScopeLogBuilder(logger, Level.FINE, "foo").setCategory("mycat").build()) {
 217             // do something
 218             new Object();
 219             try (FlowScopeLog log1 = new FlowScopeLogBuilder(logger, Level.FINER, "bar", "big", "ben").setParentScope(log).build()) {
 220                 // do something
 221                 new Object();
 222                 try (FlowScopeLog log2 = new FlowScopeLogBuilder(logger, Level.FINEST, "baz").setParentScope(log1).build()) {
 223                     // do something
 224                     new Object();
 225                 }
 226             }
 227         }
 228         fStreamHandler.flush();
 229         assertEquals("FINE: {\"ts\":0,\"ph\":\"s\",\"tid\":1,\"name\":\"foo\",\"cat\":\"mycat\",\"id\":\"0x1234\"}", fLog.getMessages().get(0));
 230         assertEquals("FINER: {\"ts\":0,\"ph\":\"s\",\"tid\":1,\"name\":\"bar\",\"cat\":\"mycat\",\"id\":\"0x1234\",\"args\":{\"big\":\"ben\"}}", fLog.getMessages().get(1));
 231         assertEquals("FINER: {\"ts\":0,\"ph\":\"f\",\"tid\":1,\"cat\":\"mycat\",\"id\":\"0x1234\"}", fLog.getMessages().get(2));
 232         assertEquals("FINE: {\"ts\":0,\"ph\":\"f\",\"tid\":1,\"cat\":\"mycat\",\"id\":\"0x1234\"}", fLog.getMessages().get(3));
 233     }
 234
 235     /**
 236      * Test flow with different loglevels
 237      */
 238     @Test
 239     public void testFlowLogLevels() {
 240         Logger logger = fLogger;
 241         assertNotNull(logger);
 242         try (FlowScopeLog log = new FlowScopeLogBuilder(logger, Level.WARNING, "foo").setCategory("mydog").build()) {
 243             try (FlowScopeLog log1 = new FlowScopeLogBuilder(logger, Level.FINE, "bar").setParentScope(log).build()) {
 244                 log1.step("barked");
 245                 new Object();
 246             }
 247         }
 248         fStreamHandler.flush();
 249         assertEquals("WARNING: {\"ts\":0,\"ph\":\"s\",\"tid\":1,\"name\":\"foo\",\"cat\":\"mydog\",\"id\":\"0x1234\"}",
 250                 fLog.getMessages().get(0));
 251         assertEquals("FINE: {\"ts\":0,\"ph\":\"s\",\"tid\":1,\"name\":\"bar\",\"cat\":\"mydog\",\"id\":\"0x1234\"}", fLog.getMessages().get(1));
 252         assertEquals("FINE: {\"ts\":0,\"ph\":\"t\",\"tid\":1,\"name\":\"barked\",\"cat\":\"mydog\",\"id\":\"0x1234\"}", fLog.getMessages().get(2));
 253         assertEquals("FINE: {\"ts\":0,\"ph\":\"f\",\"tid\":1,\"cat\":\"mydog\",\"id\":\"0x1234\"}", fLog.getMessages().get(3));
 254         assertEquals("WARNING: {\"ts\":0,\"ph\":\"f\",\"tid\":1,\"cat\":\"mydog\",\"id\":\"0x1234\"}", fLog.getMessages().get(4));
 255     }
 256
 257     /**
 258      * Test flow with different loglevels
 259      */
 260     @Test
 261     public void testFlowWithData() {
 262         Logger logger = fLogger;
 263         assertNotNull(logger);
 264         try (FlowScopeLog log = new FlowScopeLogBuilder(logger, Level.WARNING, "foo").setCategory("myspider").build()) {
 265             try (FlowScopeLog log1 = new FlowScopeLogBuilder(logger, Level.FINE, "bar").setParentScope(log).build()) {
 266                 // do something
 267                 log1.addData("return", false);
 268             }
 269         }
 270         fStreamHandler.flush();
 271         assertEquals("WARNING: {\"ts\":0,\"ph\":\"s\",\"tid\":1,\"name\":\"foo\",\"cat\":\"myspider\",\"id\":\"0x1234\"}",
 272                 fLog.getMessages().get(0));
 273         assertEquals("FINE: {\"ts\":0,\"ph\":\"s\",\"tid\":1,\"name\":\"bar\",\"cat\":\"myspider\",\"id\":\"0x1234\"}", fLog.getMessages().get(1));
 274         assertEquals("FINE: {\"ts\":0,\"ph\":\"f\",\"tid\":1,\"cat\":\"myspider\",\"id\":\"0x1234\",\"args\":{\"return\":\"false\"}}", fLog.getMessages().get(2));
 275         assertEquals("WARNING: {\"ts\":0,\"ph\":\"f\",\"tid\":1,\"cat\":\"myspider\",\"id\":\"0x1234\"}", fLog.getMessages().get(3));
 276     }
 277
 278     /**
 279      * Test the flow scope builder without calling any other method than the
 280      * constructor
 281      */
 282     @Test
 283     public void testFlowBuilderNoExtra() {
 284         Logger logger = fLogger;
 285         assertNotNull(logger);
 286         try (FlowScopeLog log = new FlowScopeLogBuilder(logger, Level.WARNING, "foo").build()) {
 287             // do something
 288             new Object();
 289         }
 290         fStreamHandler.flush();
 291         assertEquals("WARNING: {\"ts\":0,\"ph\":\"s\",\"tid\":1,\"name\":\"foo\",\"cat\":\"null\",\"id\":\"0x1234\"}",
 292                 fLog.getMessages().get(0));
 293         assertEquals("WARNING: {\"ts\":0,\"ph\":\"f\",\"tid\":1,\"cat\":\"null\",\"id\":\"0x1234\"}", fLog.getMessages().get(1));
 294     }
 295
 296     /**
 297      * Test the flow scope builder calling
 298      * {@link FlowScopeLogBuilder#setParentScope(FlowScopeLog)}, then
 299      * {@link FlowScopeLogBuilder#setCategory(String)}.
 300      */
 301     @Test(expected = IllegalStateException.class)
 302     public void testFlowBuilderCatThenParent() {
 303         Logger logger = fLogger;
 304         assertNotNull(logger);
 305         try (FlowScopeLog log = new FlowScopeLogBuilder(logger, Level.WARNING, "foo").setCategory("myspider").build()) {
 306             try (FlowScopeLog log1 = new FlowScopeLogBuilder(logger, Level.FINE, "bar").setParentScope(log).setCategory("myspider").build()) {
 307                 // do something
 308                 new Object();
 309             }
 310         }
 311     }
 312
 313     /**
 314      * Test the flow scope builder calling
 315      * {@link FlowScopeLogBuilder#setParentScope(FlowScopeLog)}, then
 316      * {@link FlowScopeLogBuilder#setCategory(String)}.
 317      */
 318     @Test(expected = IllegalStateException.class)
 319     public void testFlowBuilderParentThenCat() {
 320         Logger logger = fLogger;
 321         assertNotNull(logger);
 322         try (FlowScopeLog log = new FlowScopeLogBuilder(logger, Level.WARNING, "foo").setCategory("myspider").build()) {
 323             try (FlowScopeLog log1 = new FlowScopeLogBuilder(logger, Level.FINE, "bar").setCategory("myspider").setParentScope(log).build()) {
 324                 // do something
 325                 new Object();
 326             }
 327         }
 328     }
 329
 330     /**
 331      * Test nesting with different arguments
 332      */
 333     @Test
 334     public void testAttributes() {
 335         Logger logger = fLogger;
 336         assertNotNull(logger);
 337         try (TraceCompassLogUtils.ScopeLog log = new TraceCompassLogUtils.ScopeLog(logger, Level.WARNING, "foo", "Pen:Pineapple", "Apple:Pen")) {
 338             // do something
 339             new Object();
 340         }
 341         try (TraceCompassLogUtils.ScopeLog log = new TraceCompassLogUtils.ScopeLog(logger, Level.WARNING, "foo", "Pen:Pineapple:Apple:Pen")) {
 342             // do something
 343             new Object();
 344         }
 345         try (TraceCompassLogUtils.ScopeLog log = new TraceCompassLogUtils.ScopeLog(logger, Level.WARNING, "foo", "pen", "pineapple", "apple", "pen", "number_of_badgers", 12)) {
 346             // do something
 347             new Object();
 348         }
 349         fStreamHandler.flush();
 350         assertEquals("WARNING: {\"ts\":0,\"ph\":\"B\",\"tid\":1,\"name\":\"foo\",\"args\":{\"Pen:Pineapple\":\"Apple:Pen\"}}",
 351                 fLog.getMessages().get(0));
 352         assertEquals("WARNING: {\"ts\":0,\"ph\":\"E\",\"tid\":1}", fLog.getMessages().get(1));
 353
 354         assertEquals("WARNING: {\"ts\":0,\"ph\":\"B\",\"tid\":1,\"name\":\"foo\",\"args\":{\"msg\":\"Pen:Pineapple:Apple:Pen\"}}",
 355                 fLog.getMessages().get(2));
 356         assertEquals("WARNING: {\"ts\":0,\"ph\":\"E\",\"tid\":1}", fLog.getMessages().get(3));
 357
 358         assertEquals("WARNING: {\"ts\":0,\"ph\":\"B\",\"tid\":1,\"name\":\"foo\",\"args\":{\"pen\":\"pineapple\",\"apple\":\"pen\",\"number_of_badgers\":12}}",
 359                 fLog.getMessages().get(4));
 360         assertEquals("WARNING: {\"ts\":0,\"ph\":\"E\",\"tid\":1}", fLog.getMessages().get(5));
 361     }
 362
 363     /**
 364      * Test with an odd number of args.
 365      */
 366     @Test(expected = IllegalArgumentException.class)
 367     public void testAttributeFail3Args() {
 368         Logger logger = fLogger;
 369         assertNotNull(logger);
 370         try (TraceCompassLogUtils.ScopeLog log = new TraceCompassLogUtils.ScopeLog(logger, Level.WARNING, "foo", "Pen:Pineapple", "Apple", "Pen")) {
 371             // do something
 372             new Object();
 373         }
 374     }
 375
 376     /**
 377      * Test with a repeating key.
 378      */
 379     @Test(expected = IllegalArgumentException.class)
 380     public void testAttributeFailRepeatedArgs() {
 381         Logger logger = fLogger;
 382         assertNotNull(logger);
 383         try (TraceCompassLogUtils.ScopeLog log = new TraceCompassLogUtils.ScopeLog(logger, Level.WARNING, "foo", "badger", "badger", "badger", "badger")) {
 384             // do something
 385             new Object();
 386         }
 387     }
 388
 389     /**
 390      * Test nesting with an exception
 391      */
 392     @Test
 393     public void testNestingException() {
 394         Logger logger = fLogger;
 395         assertNotNull(logger);
 396         try (TraceCompassLogUtils.ScopeLog log = new TraceCompassLogUtils.ScopeLog(logger, Level.INFO, "foo")) {
 397             try (TraceCompassLogUtils.ScopeLog log1 = new TraceCompassLogUtils.ScopeLog(logger, Level.INFO, "bar")) {
 398                 // do something
 399                 new Object();
 400                 throw new Exception("test");
 401             }
 402         } catch (Exception e) {
 403             assertEquals("test", e.getMessage());
 404         }
 405         fStreamHandler.flush();
 406         assertEquals("INFO: {\"ts\":0,\"ph\":\"B\",\"tid\":1,\"name\":\"foo\"}", fLog.getMessages().get(0));
 407         assertEquals("INFO: {\"ts\":0,\"ph\":\"B\",\"tid\":1,\"name\":\"bar\"}", fLog.getMessages().get(1));
 408         assertEquals("INFO: {\"ts\":0,\"ph\":\"E\",\"tid\":1}", fLog.getMessages().get(2));
 409         assertEquals("INFO: {\"ts\":0,\"ph\":\"E\",\"tid\":1}", fLog.getMessages().get(3));
 410     }
 411
 412     private static final class LivingObject {
 413
 414         private final @NonNull Logger fLog;
 415
 416         public LivingObject(@NonNull Logger logger) {
 417             fLog = logger;
 418             TraceCompassLogUtils.traceObjectCreation(fLog, Level.FINE, this);
 419         }
 420
 421         @Override
 422         protected void finalize() throws Throwable {
 423             TraceCompassLogUtils.traceObjectDestruction(fLog, Level.FINE, this);
 424             super.finalize();
 425         }
 426
 427     }
 428
 429     /**
 430      * Test two objects lifecycles
 431      *
 432      * @throws Throwable
 433      *             error in finalizes
 434      */
 435     @Test
 436     public void testObjectLifespan() throws Throwable {
 437         Logger logger = fLogger;
 438         assertNotNull(logger);
 439         {
 440             LivingObject first = new LivingObject(logger);
 441             LivingObject second = new LivingObject(logger);
 442             assertNotNull(first);
 443             assertNotNull(second);
 444             // This will surely trigger some static analysis. This is for
 445             // testing purposes.
 446             first.finalize();
 447             second.finalize();
 448         }
 449
 450         fStreamHandler.flush();
 451         assertEquals("FINE: {\"ts\":0,\"ph\":\"N\",\"tid\":1,\"name\":\"LivingObject\",\"id\":\"0x1234\"}", fLog.getMessages().get(0));
 452         assertEquals("FINE: {\"ts\":0,\"ph\":\"N\",\"tid\":1,\"name\":\"LivingObject\",\"id\":\"0x1234\"}", fLog.getMessages().get(1));
 453         assertEquals("FINE: {\"ts\":0,\"ph\":\"D\",\"tid\":1,\"name\":\"LivingObject\",\"id\":\"0x1234\"}", fLog.getMessages().get(2));
 454         assertEquals("FINE: {\"ts\":0,\"ph\":\"D\",\"tid\":1,\"name\":\"LivingObject\",\"id\":\"0x1234\"}", fLog.getMessages().get(3));
 455     }
 456
 457     /**
 458      * Test two objects lifecycles
 459      */
 460     @Test
 461     public void testCollectionLifespan() {
 462         Logger logger = fLogger;
 463         assertNotNull(logger);
 464         {
 465             List<String> avengers = new ArrayList<>();
 466             int uniqueID = TraceCompassLogUtils.traceObjectCreation(logger, Level.FINE, avengers);
 467             avengers.add("Cap");
 468             avengers.add("Arrow");
 469             avengers.add("Thor");
 470             avengers.add("Iron");
 471             TraceCompassLogUtils.traceObjectDestruction(logger, Level.FINE, avengers, uniqueID);
 472
 473         }
 474
 475         fStreamHandler.flush();
 476         assertEquals("FINE: {\"ts\":0,\"ph\":\"N\",\"tid\":1,\"name\":\"ArrayList\",\"id\":\"0x1234\"}", fLog.getMessages().get(0));
 477         assertEquals("FINE: {\"ts\":0,\"ph\":\"D\",\"tid\":1,\"name\":\"ArrayList\",\"id\":\"0x1234\"}", fLog.getMessages().get(1));
 478     }
 479
 480     /**
 481      * Test instant events
 482      */
 483     @Test
 484     public void testInstant() {
 485         Logger logger = fLogger;
 486         assertNotNull(logger);
 487         TraceCompassLogUtils.traceInstant(logger, Level.FINE, "hello", "foo", "bar");
 488         fStreamHandler.flush();
 489         assertEquals("FINE: {\"ts\":0,\"ph\":\"i\",\"tid\":1,\"name\":\"hello\",\"args\":{\"foo\":\"bar\"}}", fLog.getMessages().get(0));
 490     }
 491
 492     /**
 493      * Test asynchronous messages
 494      */
 495     @Test
 496     public void testAsyncMessages() {
 497         Logger logger = fLogger;
 498         assertNotNull(logger);
 499         TraceCompassLogUtils.traceAsyncStart(logger, Level.FINE, "network connect", "net", 10);
 500         TraceCompassLogUtils.traceAsyncStart(logger, Level.FINER, "network lookup", "net", 10);
 501         TraceCompassLogUtils.traceAsyncNested(logger, Level.FINER, "network cache", "net", 10);
 502         // anon message
 503         TraceCompassLogUtils.traceAsyncStart(logger, Level.FINER, null, null, 0);
 504         TraceCompassLogUtils.traceAsyncEnd(logger, Level.FINER, null, null, 0);
 505
 506         TraceCompassLogUtils.traceAsyncEnd(logger, Level.FINER, "network lookup", "net", 10, "OK");
 507         TraceCompassLogUtils.traceAsyncEnd(logger, Level.FINE, "network connect", "net", 10, "OK");
 508
 509         fStreamHandler.flush();
 510         assertEquals("FINE: {\"ts\":0,\"ph\":\"b\",\"tid\":1,\"name\":\"network connect\",\"cat\":\"net\",\"id\":\"0x1234\"}", fLog.getMessages().get(0));
 511         assertEquals("FINER: {\"ts\":0,\"ph\":\"b\",\"tid\":1,\"name\":\"network lookup\",\"cat\":\"net\",\"id\":\"0x1234\"}", fLog.getMessages().get(1));
 512         assertEquals("FINER: {\"ts\":0,\"ph\":\"n\",\"tid\":1,\"name\":\"network cache\",\"cat\":\"net\",\"id\":\"0x1234\"}", fLog.getMessages().get(2));
 513         assertEquals("FINER: {\"ts\":0,\"ph\":\"b\",\"tid\":1,\"id\":\"0x1234\"}", fLog.getMessages().get(3));
 514         assertEquals("FINER: {\"ts\":0,\"ph\":\"e\",\"tid\":1,\"id\":\"0x1234\"}", fLog.getMessages().get(4));
 515         assertEquals("FINER: {\"ts\":0,\"ph\":\"e\",\"tid\":1,\"name\":\"network lookup\",\"cat\":\"net\",\"id\":\"0x1234\",\"args\":{\"msg\":\"OK\"}}", fLog.getMessages().get(5));
 516         assertEquals("FINE: {\"ts\":0,\"ph\":\"e\",\"tid\":1,\"name\":\"network connect\",\"cat\":\"net\",\"id\":\"0x1234\",\"args\":{\"msg\":\"OK\"}}", fLog.getMessages().get(6));
 517     }
 518
 519 }