Adding logging tag to identify requests #228

schmidt-sebastian · 2018-06-27T17:46:01Z

For clients that use multiple streams in parallel, it is currently pretty hard to identify what log message correlate to which stream. This PR fixes this and tags the logline with a unique request ID that is used throughout an operations lifetime:

Firestore (0.14.1) 2018-06-27T17:45:08.120Z ##### [Firestore]: Initialized Firestore
Firestore (0.14.1) 2018-06-27T17:45:08.123Z qsSNg [WriteBatch.commit]: Sending 1 writes
Firestore (0.14.1) 2018-06-27T17:45:08.150Z ##### [Firestore]: Initialized Firestore GAPIC Client
Firestore (0.14.1) 2018-06-27T17:45:08.152Z ##### [Firestore._ensureClient]: Detected project ID: node-review
Firestore (0.14.1) 2018-06-27T17:45:08.155Z qsSNg [Firestore.request]: Sending request: {"database":"projects/node-review/databases/(default)","writes":[{"update":{"name":"projects/node-review/databases/(default)/documents/node_0.14.1_thn4G5JVQ5sMinovfHQU/oxeXCjUOkiZlQvmrTxpx","fields":{"foo":{"valueType":"stringValue","stringValue":"a"}}},"currentDocument":{"exists":false}}]}
Firestore (0.14.1) 2018-06-27T17:45:08.672Z qsSNg [Firestore.request]: Received response: {"writeResults":[{"transformResults":[],"updateTime":{"seconds":"1530121508","nanos":620688000}}],"commitTime":{"seconds":"1530121508","nanos":620688000}}
Firestore (0.14.1) 2018-06-27T17:45:08.672Z cHU8c [Firestore.readStream]: Sending request: {"database":"projects/node-review/databases/(default)","documents":["projects/node-review/databases/(default)/documents/node_0.14.1_thn4G5JVQ5sMinovfHQU/oxeXCjUOkiZlQvmrTxpx"]}
Firestore (0.14.1) 2018-06-27T17:45:08.781Z cHU8c [Firestore.readStream]: Received response: {"transaction":[],"readTime":{"seconds":"1530121508","nanos":741889000},"found":{"fields":{"foo":{"stringValue":"a","valueType":"stringValue"}},"name":"projects/node-review/databases/(default)/documents/node_0.14.1_thn4G5JVQ5sMinovfHQU/oxeXCjUOkiZlQvmrTxpx","createTime":{"seconds":"1530121508","nanos":620688000},"updateTime":{"seconds":"1530121508","nanos":620688000}},"result":"found"}
Firestore (0.14.1) 2018-06-27T17:45:08.782Z cHU8c [Firestore._initializeStream]: Releasing stream
Firestore (0.14.1) 2018-06-27T17:45:08.783Z cHU8c [Firestore.getAll_]: Received document: projects/node-review/databases/(default)/documents/node_0.14.1_thn4G5JVQ5sMinovfHQU/oxeXCjUOkiZlQvmrTxpx
Firestore (0.14.1) 2018-06-27T17:45:08.784Z cHU8c [Firestore._initializeStream]: Received stream end
Firestore (0.14.1) 2018-06-27T17:45:08.785Z cHU8c [Firestore.getAll_]: Received 1 results

This is overall a pretty ugly implementation. If you can think of a better way, let me know.

src/watch.js

          self._backoff.resetToMax();
        }

        resetStream();
      } else {
-        Firestore.log('Watch.onSnapshot', 'Stream ended, sending error: ', err);


hiranya911

Looks mostly good. Just a few nits to think about.

src/index.js

@@ -518,6 +518,7 @@ follow these steps, YOUR APP MAY BREAK.`);
    }

    let transaction = new Transaction(this, previousTransaction);
+    let requestTag = transaction.requestTag;


src/index.js

+   * @returns {string} A random 5-character wide identifier.
+   */
+  static requestTag() {
+    return Firestore.autoId().substr(0, 5);


src/reference.js


    return this._firestore
-      .request('listCollectionIds', request)
+      .request('listCollectionIds', request, requestTag)


src/index.js

@@ -1160,7 +1236,7 @@ follow these steps, YOUR APP MAY BREAK.`);
 * @private
 * @type {Firestore~logFunction}
 */
-Firestore.log = function() {};
+Firestore.log = function(methodName, logMessage, varargs) {};


src/index.js

@@ -1172,13 +1248,15 @@ Firestore.log = function() {};
 Firestore.setLogFunction = function(logger) {
  validate.isFunction('logger', logger);

-  Firestore.log = function(methodName, varargs) {
-    varargs = Array.prototype.slice.call(arguments, 1);
+  Firestore.log = function(methodName, requestTag, varargs) {


src/transaction.js

@@ -299,7 +314,7 @@ class Transaction {
    }

    return this._firestore
-      .request('beginTransaction', request, /* allowRetries= */ true)
+      .request('beginTransaction', request, this._requestTag, true)


src/transaction.js

+   * @private
+   * @return {string} A unique client-generated identifier for this transaction.
+   */
+  get requestTag() {


src/watch.js

+   * @param {Error} error An error object.
+   * @return {boolean} Whether the error is permanent.
+   */
+  isPermanentError(error) {


codecov · 2018-06-27T21:32:53Z

Codecov Report

Merging #228 into master will not change coverage.
The diff coverage is 100%.

@@          Coverage Diff          @@
##           master   #228   +/-   ##
=====================================
  Coverage     100%   100%           
=====================================
  Files          13     13           
  Lines        1837   1846    +9     
=====================================
+ Hits         1837   1846    +9

Impacted Files	Coverage Δ
src/watch.js	`100% <100%> (ø)`	⬆️
src/transaction.js	`100% <100%> (ø)`	⬆️
src/reference.js	`100% <100%> (ø)`	⬆️
src/index.js	`100% <100%> (ø)`	⬆️
src/write-batch.js	`100% <100%> (ø)`	⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 6c1f409...4f57bd9. Read the comment docs.

schmidt-sebastian

Thanks for the review. Comments addressed.

src/index.js

@@ -518,6 +518,7 @@ follow these steps, YOUR APP MAY BREAK.`);
    }

    let transaction = new Transaction(this, previousTransaction);
+    let requestTag = transaction.requestTag;


src/index.js

+   * @returns {string} A random 5-character wide identifier.
+   */
+  static requestTag() {
+    return Firestore.autoId().substr(0, 5);


src/index.js

@@ -1160,7 +1236,7 @@ follow these steps, YOUR APP MAY BREAK.`);
 * @private
 * @type {Firestore~logFunction}
 */
-Firestore.log = function() {};
+Firestore.log = function(methodName, logMessage, varargs) {};


src/index.js

@@ -1172,13 +1248,15 @@ Firestore.log = function() {};
 Firestore.setLogFunction = function(logger) {
  validate.isFunction('logger', logger);

-  Firestore.log = function(methodName, varargs) {
-    varargs = Array.prototype.slice.call(arguments, 1);
+  Firestore.log = function(methodName, requestTag, varargs) {


src/reference.js


    return this._firestore
-      .request('listCollectionIds', request)
+      .request('listCollectionIds', request, requestTag)


src/transaction.js

+   * @private
+   * @return {string} A unique client-generated identifier for this transaction.
+   */
+  get requestTag() {


src/watch.js

+   * @param {Error} error An error object.
+   * @return {boolean} Whether the error is permanent.
+   */
+  isPermanentError(error) {


…-firestore into requestlogging

hiranya911

LGTM with a nit.

laurenzlong

Approved based on Hiranya's review, and the fact that his comment was addressed.

Adding logging tag to identify requests

e909742

googlebot added the cla: yes This human has signed the Contributor License Agreement. label Jun 27, 2018

schmidt-sebastian commented Jun 27, 2018

View reviewed changes

src/watch.js

self._backoff.resetToMax();

}

resetStream();

} else {

Firestore.log('Watch.onSnapshot', 'Stream ended, sending error: ', err);

This comment was marked as spam.

Sign in to view

Merge branch 'master' into requestlogging

ebedd1a

hiranya911 suggested changes Jun 27, 2018

View reviewed changes

Addressing comments

c0cd9e6

schmidt-sebastian commented Jun 27, 2018

View reviewed changes

schmidt-sebastian added 3 commits June 28, 2018 10:02

Merge branch 'master' into requestlogging

3f75db7

Merge

082f2eb

Merge branch 'requestlogging' of https://github.com/googleapis/nodejs…

b3392c9

…-firestore into requestlogging

ghost assigned schmidt-sebastian Jun 29, 2018

ghost added the in progress label Jun 29, 2018

hiranya911 approved these changes Jun 29, 2018

View reviewed changes

Adding ALLOW_RETRIES constant

4f57bd9

schmidt-sebastian assigned stephenplusplus and unassigned schmidt-sebastian Jun 29, 2018

laurenzlong approved these changes Jun 29, 2018

View reviewed changes

schmidt-sebastian merged commit 2755458 into master Jun 29, 2018

ghost removed the in progress label Jun 29, 2018

schmidt-sebastian deleted the requestlogging branch July 24, 2018 04:27

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Adding logging tag to identify requests #228

Adding logging tag to identify requests #228

schmidt-sebastian commented Jun 27, 2018

This comment was marked as spam.

hiranya911 left a comment

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

codecov bot commented Jun 27, 2018 •

edited

Loading

schmidt-sebastian left a comment

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

hiranya911 left a comment

laurenzlong left a comment

Adding logging tag to identify requests #228

Adding logging tag to identify requests #228

Conversation

schmidt-sebastian commented Jun 27, 2018

This comment was marked as spam.

hiranya911 left a comment

Choose a reason for hiding this comment

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

codecov bot commented Jun 27, 2018 • edited Loading

Codecov Report

schmidt-sebastian left a comment

Choose a reason for hiding this comment

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

hiranya911 left a comment

Choose a reason for hiding this comment

laurenzlong left a comment

Choose a reason for hiding this comment

codecov bot commented Jun 27, 2018 •

edited

Loading