Speculative logging for PostHog/posthog#4816 (#293)

* speculative logging for PostHog/posthog#4816

* use capture metrics to send debug messages home

* adds tests and only sends debug "metrics" when debug is enabled

* only check one flag before logging debug 'metrics'

* update tests now that debug flag is not used in capture metrics:

* add information to README on how to use yalc to develop locally

* catch errors in new debug logging to avoid this check affecting users on error

* remove usage of debug enabled as a parameter to capture metrics

* add instructions to remove yalc linkage

README.md

@@ -28,8 +28,40 @@ Use [`yarn link`](https://classic.yarnpkg.com/en/docs/cli/link/). Run `yarn link
 
 An alternative is to update dependency in package.json to e.g. `"posthog-js": "link:../posthog-js"`, `yarn` and run `yarn build && yarn build-module`
 
+## Alternative to yarn link
 
-### Developing with main PostHog repo
+Run `npm install -g yalc`
+
+In the posthog-js repo
+
+* run `yalc publish`
+
+In the posthog repo
+
+* run `yalc add posthog-js`
+* run `yarn`
+* run `yarn copy-scripts`
+
+### When making changes
+
+In the posthog-js repo
+
+* run `yalc publish`
+
+In the posthog repo
+
+* run `yalc update`
+* run `yarn`
+* run `yarn copy-scripts`
+
+### To remove the local package
+
+In the posthog repo
+
+* run `yalc remove posthog-js`
+* run `yarn install`
+
+## Developing with main PostHog repo
 
 The `posthog-js` snippet for a website loads static js from the main `PostHog/posthog` repo. Which means, when testing the snippet with a website, there's a bit of extra setup required:
 

src/__tests__/capture-metrics.js

@@ -9,7 +9,6 @@ describe('CaptureMetrics()', () => {
 
     given('enabled', () => true)
     given('capture', () => jest.fn())
-
     given('getTime', () => jest.fn())
 
     describe('incr() and decr()', () => {
@@ -85,8 +84,32 @@ describe('CaptureMetrics()', () => {
             given.captureMetrics.captureInProgressRequests()
             given.captureMetrics.markRequestFailed({ foo: 'bar' })
             given.captureMetrics.finishRequest(null)
+            given.captureMetrics.addDebugMessage('tomato', 'potato')
 
             expect(given.capture).not.toHaveBeenCalled()
         })
+
+        describe('logging debug messages via metrics', () => {
+            it('does nothing if not enabled', () => {
+                given('enabled', () => false)
+
+                given.captureMetrics.addDebugMessage('tomato', 'potato')
+
+                expect(given.captureMetrics.metrics).toEqual({})
+            })
+
+            it('does something if capture metrics is enabled', () => {
+                given('enabled', () => true)
+
+                given.captureMetrics.addDebugMessage('tomato', 'potato')
+                given.captureMetrics.addDebugMessage('potato', 'salad')
+                given.captureMetrics.addDebugMessage('potato', 'chips')
+
+                expect(given.captureMetrics.metrics).toEqual({
+                    'phjs-debug-tomato': ['potato'],
+                    'phjs-debug-potato': ['salad', 'chips'],
+                })
+            })
+        })
     })
 })

src/capture-metrics.js

@@ -23,6 +23,16 @@ export class CaptureMetrics {
         }
     }
 
+    addDebugMessage(key, payload) {
+        if (this.enabled) {
+            key = `phjs-debug-${key}`
+            if (!this.metrics[key]) {
+                this.metrics[key] = []
+            }
+            this.metrics[key].push(payload)
+        }
+    }
+
     startRequest(payload) {
         if (this.enabled) {
             const requestId = _.UUID()

src/compression.js

@@ -12,15 +12,43 @@ export function decideCompression(compressionSupport) {
     }
 }
 
-export function compressData(compression, jsonData, options) {
+function hasMagicGzipHeader(compressionResultElement) {
+    try {
+        const a = compressionResultElement[0]
+        const b = compressionResultElement[1]
+        return a === 31 && b === 139
+    } catch (e) {
+        return false
+    }
+}
+
+export function compressData(compression, jsonData, options, captureMetrics) {
     if (compression === 'lz64') {
         return [{ data: LZString.compressToBase64(jsonData), compression: 'lz64' }, options]
     } else if (compression === 'gzip-js') {
         // :TRICKY: This returns an UInt8Array. We don't encode this to a string - returning a blob will do this for us.
-        return [
+        const compressionResult = [
             gzipSync(strToU8(jsonData), { mtime: 0 }),
             { ...options, blob: true, urlQueryArgs: { compression: 'gzip-js' } },
         ]
+
+        // temporary logging to identify source of https://github.com/PostHog/posthog/issues/4816
+        try {
+            const jsonDataIsUnexpected = !jsonData || jsonData === 'undefined'
+            if (jsonDataIsUnexpected || !compressionResult[0] || !hasMagicGzipHeader(compressionResult[0])) {
+                captureMetrics.addDebugMessage('PostHogJSCompressionCannotBeDecompressed', {
+                    jsonData,
+                    compressionResult: compressionResult[0],
+                })
+            }
+        } catch (e) {
+            captureMetrics.addDebugMessage('PostHogJSCompressionCannotBeDecompressed-error', {
+                error: e,
+                message: e.message,
+            })
+        }
+
+        return compressionResult
     } else {
         return [{ data: _.base64Encode(jsonData) }, options]
     }

src/posthog-core.js

@@ -368,7 +368,7 @@ PostHogLib.prototype._handle_queued_event = function (url, data, options) {
 }
 
 PostHogLib.prototype.__compress_and_send_json_request = function (url, jsonData, options, callback) {
-    const [data, _options] = compressData(decideCompression(this.compression), jsonData, options)
+    const [data, _options] = compressData(decideCompression(this.compression), jsonData, options, this._captureMetrics)
     this._send_request(url, data, _options, callback)
 }