generalize 'log' query parameter?

[pixelzoom]

See code snippet below from equality-explorer. This is the latest iteration of something I'm been doing in most of my sim-specific *QueryParameters.js files. I'm wondering if it's worth generalizing.

In a nutshell... When ?log is provided, it adds a log function to the sim's namespace, then prints the value of all sim-specific query parameters at startup. If generalized, it might be more appropriate to add log to something other than the sim's namespace (a global? a common-code namespace?)

  //TODO migrate to common code? This is a pattern that I've been repeating.
  if ( EqualityExplorerQueryParameters.log ) {

    // add a log function that displays messages in green
    equalityExplorer.log = function( message ) {
      console.log( '%clog: ' + message, 'color: #009900' );
    };

    // log the values of all query parameters
    for ( var property in EqualityExplorerQueryParameters ) {
      if ( EqualityExplorerQueryParameters.hasOwnProperty( property ) ) {
        equalityExplorer.log( property + '=' + EqualityExplorerQueryParameters[ property ] );
      }
    }
  }

[pixelzoom]

I recall that we previously discussed the generalization of logging. But I don't recall our conclusions, and can't find the specific issue.

[jonathanolson]

Scenery has some logging functionality in scenery.js, and it could use generalization (there are some other places besides Scenery where people are logging things in a similar way).

[pixelzoom]

All devs: If you have a logging pattern that you're using, please add an example (or pointer to an example) to this issue.

[jonathanolson]

sceneryLog && sceneryLog.{{LOG_NAME}} && sceneryLog.{{LOG_NAME}}( {{MESSAGE}} );

also with push/pops:

sceneryLog && sceneryLog.{{LOG_NAME}} && sceneryLog.{{LOG_NAME}}( {{MESSAGE}} );
sceneryLog && sceneryLog.{{LOG_NAME}} && sceneryLog.push();
// ... in-between stuff gets indented another level
sceneryLog && sceneryLog.{{LOG_NAME}} && sceneryLog.pop();

and each log name can have an additional associated style.

Results in output similar to: which is quite helpful to debug complicated Scenery things. Looks like I have 713 instances of sceneryLog && in Scenery.

[pixelzoom]

9/7/17 dev meeting note: Deferred. @jbphet (and any other devs) please identify the pattern that you're using.

[samreid]

All devs: If you have a logging pattern that you're using, please add an example (or pointer to an example) to this issue.

ModifiedNodalAnalysisCircuit.js

      var DEBUG = CircuitConstructionKitCommonQueryParameters.debugModifiedNodalAnalysis;
      // ...
      DEBUG && console.log( 'Debugging circuit: ' + this.toString() );
      DEBUG && console.log( equations.join( '\n' ) );
      DEBUG && console.log( 'A=\n' + A.toString() );
      DEBUG && console.log( 'z=\n' + z.toString() );
      DEBUG && console.log( 'unknowns=\n' + unknowns.map( function( u ) {
        return u.toString();
      } ).join( '\n' ) );

[jbphet]

In expression exchange, I have the following in the EEQueryParameters file:

    // turn on logging of coin term and expression creation and removal
    enableLogging: { type: 'flag' },

In expression-exchange-main.js, the logging function is added like this:

  // Add support for logging if specified.  This is intended for debug of things like coin term and expression creation
  // and removal, so it doesn't need to be enabled before the module loading (RequireJS) phase.
  if ( EEQueryParameters.enableLogging ) {
    console.log( 'enabling log' );
    expressionExchange.log = function( message ) {
      console.log( '%clog: ' + message, 'color: #009900' ); // green
    };
  }

Finally, in various places within the sim code the logging is used like so:

      expressionExchange.log && expressionExchange.log( 'removed ' + coinTerm.id + ' from ' + this.id );

[pixelzoom]

Looks like @jbphet and I are using the same approach, with 2 differences:

(1) log vs enableLogging query parameter name. I prefer the less verbose log.

(2) Adding to namespace in *QueryParameter.js vs in *main.js. I prefer to keep this encapsulated in *QueryParameter.js (e.g. EqualityExplorerQueryParameters.js), because *main.js (e.g. expression-exchange-main.js) typically has no need to know about query parameters.

[pixelzoom]

@samreid's approach (see https://github.com/phetsims/query-string-machine/issues/28#issuecomment-327854364) is also similar to what @jbphet and I are doing. It doesn't make a global log function available, and it provides no encapsulation of console.log. If we want to change how logging is done, we need to change every DEBUG && console.log line.

[pixelzoom]

Proposal for changes to initialize-globals.js

(1) Add to QUERY_PARAMETERS_SCHEMA:

    // Enables console logging.
    log: { type: 'flag' },

(2) After the call to QueryStringMachine.getAll( QUERY_PARAMETERS_SCHEMA ) on line 338, add:

if ( window.phet.chipper.queryParameters.log ) {

    // add a log function that displays messages in green
    window.phet.log = function( message ) {
      console.log( '%clog: ' + message, 'color: #009900' );
    };
} 

Usage by clients:

phet.log && phet.log( 'some log message' );

Or we continue to duplicate variations of this code.

[samreid]

Is the color helpful? What about people using dark dev tools?

Why not put phet.log = function(){} when the flag is off, then there will be no need to short circuit in the usage by clients?

phet.log('some log message');

Also, it seems suboptimal that console.log and phet.log have radically different behavior regarding multi-arguments and object formatting. Why not use something like console.log.call(null,arguments) for its implementation? (untested, but you get the idea).

Also, how is the "log:" prefix helpful? Can it be eliminated?

[pixelzoom]

The color is helpful to me. It distinguished between log messages and plain old console.log calls.

phet.log = function(){} is not zero work, it's still a function call. Not sure if that's significant or not.

This is (at least) the second time that we've discussed logging. And I don't feel like we're making any progress. So I'm going to unassign and bow out for now, I don't have time. If someone wants to champion this issue, please self assign. In the meantime, I will continue to duplicate code in my *QueryParameters.js files.

[samreid]

phet.log = function(){} is not zero work, it's still a function call. Not sure if that's significant or not.

Right, for performance critical sims it would be nice to eliminate the overhead, even if called rarely. We could even get these lines stripped out if we prefix it with assert or use the same strategy we use for stripping asserts.

The color is helpful to me. It distinguished between log messages and plain old console.log calls.

When should a developer use console.log vs phet.log? I'm trying to understand what would cause a mix of console.log statements and phet.log statements.

[pixelzoom]

phet.log is for logging that remains in the code, and can be enabled via query parameter. console.log is for something that you intended to remove (assuming you actually follow through on that intention). Published sims should generally not write to the console.

[pixelzoom]

9/14/17 dev meeting: Consensus was to add as proposed in https://github.com/phetsims/query-string-machine/issues/28#issuecomment-328966331. I'm do so. Use it if you wish.

[pixelzoom]

phet.log and ?log have been added, as proposed in https://github.com/phetsims/query-string-machine/issues/28#issuecomment-328966331.

@pixelzoom and @jbphet sims have been changed to use phet.log.

Assigning to @jbphet to review changes I made to expression-exchange, and the changes to initialize-globals.js.

Assigning to @samreid to evaluate whether to use phet.log instead of DEBUG && console.log.

[pixelzoom]

In https://github.com/phetsims/query-string-machine/issues/28#issuecomment-328968367, @samreid said:

Is the color helpful? What about people using dark dev tools?

At 9/14/17 dev meeting, the consensus was that color is helpful.

If the current color of the log message (green) is an issue for anyone, we could add a logColor query parameter. But green seems to work nicely on white and black backgrounds, so I'm hoping this is a non-issue.

[samreid]

I converted CCKC to use the log query parameter in the preceding commit. The only other occurrences of DEBUG && console.log are in Molecule Polarity. Reassigned to @pixelzoom to see if he wants to address those or not.

[pixelzoom]

Thanks, molecule-polarity is now using phet.log.

[jbphet]

Changes for expression-exchange and initialize-globals.js look good. I tested the logging in expression-exchange, and it behaves as it did prior to these changes (which was the goal). Back to @pixelzoom - it may be safe to close, but he'd be more aware of any loose ends than I.

[pixelzoom]

No loose ends that I can recall. Closing.