feat: Added better sub logging utils (#1581)

functional_tests/feature-flags.test.ts

@@ -1,3 +1,5 @@
+import '../src/__tests__/helpers/mock-logger'
+
 import { createPosthogInstance } from '../src/__tests__/helpers/posthog-instance'
 import { waitFor } from '@testing-library/dom'
 import { getRequests, resetRequests } from './mock-server'

functional_tests/identify.test.ts

@@ -1,11 +1,12 @@
+import '../src/__tests__/helpers/mock-logger'
+
 import 'regenerator-runtime/runtime'
 import { waitFor } from '@testing-library/dom'
 import { getRequests } from './mock-server'
 import { createPosthogInstance } from '../src/__tests__/helpers/posthog-instance'
 import { logger } from '../src/utils/logger'
 import { uuidv7 } from '../src/uuidv7'
 import { PostHog } from '../src/posthog-core'
-jest.mock('../src/utils/logger')
 
 describe('FunctionalTests / Identify', () => {
     let token: string

src/__tests__/consent.test.ts

@@ -1,3 +1,5 @@
+import './helpers/mock-logger'
+
 import { PostHog } from '../posthog-core'
 import { defaultPostHog } from './helpers/posthog-instance'
 import { uuidv7 } from '../uuidv7'

src/__tests__/decide.ts

@@ -212,7 +212,10 @@ describe('Decide', () => {
             subject(undefined as unknown as DecideResponse)
 
             expect(posthog.featureFlags.receivedFeatureFlags).toHaveBeenCalledWith({}, true)
-            expect(console.error).toHaveBeenCalledWith('[PostHog.js]', 'Failed to fetch feature flags from PostHog.')
+            expect(console.error).toHaveBeenCalledWith(
+                '[PostHog.js] [Decide]',
+                'Failed to fetch feature flags from PostHog.'
+            )
         })
 
         it('Make sure receivedFeatureFlags is not called if advanced_disable_feature_flags_on_first_load is set', () => {

src/__tests__/extensions/web-vitals.test.ts

@@ -1,11 +1,12 @@
+import '../helpers/mock-logger'
+
 import { createPosthogInstance } from '../helpers/posthog-instance'
 import { uuidv7 } from '../../uuidv7'
 import { PostHog } from '../../posthog-core'
 import { DecideResponse, PerformanceCaptureConfig, SupportedWebVitalsMetrics } from '../../types'
 import { assignableWindow } from '../../utils/globals'
 import { DEFAULT_FLUSH_TO_CAPTURE_TIMEOUT_MILLISECONDS, FIFTEEN_MINUTES_IN_MILLIS } from '../../extensions/web-vitals'
 
-jest.mock('../../utils/logger')
 jest.useFakeTimers()
 
 describe('web vitals', () => {

src/__tests__/featureflags.ts

@@ -87,15 +87,15 @@ describe('featureflags', () => {
         expect(featureFlags.getFlags()).toEqual([])
         expect(featureFlags.isFeatureEnabled('beta-feature')).toEqual(undefined)
         expect(window.console.warn).toHaveBeenCalledWith(
-            '[PostHog.js]',
+            '[PostHog.js] [FeatureFlags]',
             'isFeatureEnabled for key "beta-feature" failed. Feature flags didn\'t load in time.'
         )
 
         mockWarn.mockClear()
 
         expect(featureFlags.getFeatureFlag('beta-feature')).toEqual(undefined)
         expect(window.console.warn).toHaveBeenCalledWith(
-            '[PostHog.js]',
+            '[PostHog.js] [FeatureFlags]',
             'getFeatureFlag for key "beta-feature" failed. Feature flags didn\'t load in time.'
         )
     })
@@ -246,7 +246,7 @@ describe('featureflags', () => {
             'alpha-feature-2': true,
         })
         expect(window.console.warn).toHaveBeenCalledWith(
-            '[PostHog.js]',
+            '[PostHog.js] [FeatureFlags]',
             ' Overriding feature flags!',
             expect.any(Object)
         )

src/__tests__/heatmaps.test.ts

@@ -1,3 +1,5 @@
+import './helpers/mock-logger'
+
 import { createPosthogInstance } from './helpers/posthog-instance'
 import { uuidv7 } from '../uuidv7'
 import { PostHog } from '../posthog-core'
@@ -7,7 +9,6 @@ import { beforeEach, expect } from '@jest/globals'
 import { HEATMAPS_ENABLED_SERVER_SIDE } from '../constants'
 import { Heatmaps } from '../heatmaps'
 
-jest.mock('../utils/logger')
 jest.useFakeTimers()
 
 describe('heatmaps', () => {

src/__tests__/helpers/mock-logger.ts

@@ -0,0 +1,32 @@
+import { Logger } from '../../utils/logger'
+
+jest.mock('../../utils/logger', () => {
+    const mockLogger: Logger = {
+        _log: jest.fn(),
+        critical: jest.fn(),
+        uninitializedWarning: jest.fn(),
+        info: jest.fn(),
+        warn: jest.fn(),
+        error: jest.fn(),
+        createLogger: () => {
+            return mockLogger
+        },
+    }
+    return {
+        logger: mockLogger,
+        createLogger: mockLogger.createLogger,
+    }
+})
+
+import { logger } from '../../utils/logger'
+import { isFunction } from '../../utils/type-utils'
+
+export const clearLoggerMocks = () => {
+    Object.values(logger).forEach((mock: any) => {
+        if (isFunction(mock.mockClear)) {
+            mock.mockClear()
+        }
+    })
+}
+
+export const mockLogger: jest.Mocked<Logger> = logger as any

src/__tests__/identify.test.ts

@@ -1,7 +1,7 @@
+import { mockLogger } from './helpers/mock-logger'
+
 import { createPosthogInstance } from './helpers/posthog-instance'
-import { logger } from '../utils/logger'
 import { uuidv7 } from '../uuidv7'
-jest.mock('../utils/logger')
 
 describe('identify', () => {
     // Note that there are other tests for identify in posthog-core.identify.js
@@ -19,8 +19,8 @@ describe('identify', () => {
 
         // assert
         expect(posthog.persistence!.properties()['$user_id']).toEqual(distinctId)
-        expect(jest.mocked(logger).error).toBeCalledTimes(0)
-        expect(jest.mocked(logger).warn).toBeCalledTimes(0)
+        expect(mockLogger.error).toBeCalledTimes(0)
+        expect(mockLogger.warn).toBeCalledTimes(0)
     })
 
     it('should convert a numeric distinct_id to a string', async () => {
@@ -35,8 +35,8 @@ describe('identify', () => {
 
         // assert
         expect(posthog.persistence!.properties()['$user_id']).toEqual(distinctIdString)
-        expect(jest.mocked(logger).error).toBeCalledTimes(0)
-        expect(jest.mocked(logger).warn).toBeCalledTimes(1)
+        expect(mockLogger.error).toBeCalledTimes(0)
+        expect(mockLogger.warn).toBeCalledTimes(1)
     })
 
     it('should send $is_identified = true with the identify event and following events', async () => {

src/__tests__/personProcessing.test.ts

@@ -1,11 +1,10 @@
+import { mockLogger } from './helpers/mock-logger'
+
 import { createPosthogInstance } from './helpers/posthog-instance'
 import { uuidv7 } from '../uuidv7'
-import { logger } from '../utils/logger'
 import { INITIAL_CAMPAIGN_PARAMS, INITIAL_REFERRER_INFO } from '../constants'
 import { RemoteConfig } from '../types'
 
-jest.mock('../utils/logger')
-
 const INITIAL_CAMPAIGN_PARAMS_NULL = {
     $initial_current_url: null,
     $initial_dclid: null,
@@ -156,8 +155,8 @@ describe('person processing', () => {
             posthog.identify(distinctId)
 
             // assert
-            expect(jest.mocked(logger).error).toBeCalledTimes(1)
-            expect(jest.mocked(logger).error).toHaveBeenCalledWith(
+            expect(mockLogger.error).toBeCalledTimes(1)
+            expect(mockLogger.error).toHaveBeenCalledWith(
                 'posthog.identify was called, but process_person is set to "never". This call will be ignored.'
             )
             expect(beforeSendMock).toBeCalledTimes(0)
@@ -172,7 +171,7 @@ describe('person processing', () => {
             posthog.identify(distinctId)
             posthog.capture('custom event after identify')
             // assert
-            expect(jest.mocked(logger).error).toBeCalledTimes(0)
+            expect(mockLogger.error).toBeCalledTimes(0)
             const eventBeforeIdentify = beforeSendMock.mock.calls[0]
             expect(eventBeforeIdentify[0].properties.$process_person_profile).toEqual(false)
             const identifyCall = beforeSendMock.mock.calls[1]
@@ -191,7 +190,7 @@ describe('person processing', () => {
             posthog.identify(distinctId)
             posthog.capture('custom event after identify')
             // assert
-            expect(jest.mocked(logger).error).toBeCalledTimes(0)
+            expect(mockLogger.error).toBeCalledTimes(0)
             const eventBeforeIdentify = beforeSendMock.mock.calls[0]
             expect(eventBeforeIdentify[0].properties.$process_person_profile).toEqual(true)
             const identifyCall = beforeSendMock.mock.calls[1]
@@ -503,8 +502,8 @@ describe('person processing', () => {
             posthog.capture('custom event after group')
 
             // assert
-            expect(jest.mocked(logger).error).toBeCalledTimes(1)
-            expect(jest.mocked(logger).error).toHaveBeenCalledWith(
+            expect(mockLogger.error).toBeCalledTimes(1)
+            expect(mockLogger.error).toHaveBeenCalledWith(
                 'posthog.group was called, but process_person is set to "never". This call will be ignored.'
             )
 
@@ -526,8 +525,8 @@ describe('person processing', () => {
 
             // assert
             expect(beforeSendMock).toBeCalledTimes(0)
-            expect(jest.mocked(logger).error).toBeCalledTimes(1)
-            expect(jest.mocked(logger).error).toHaveBeenCalledWith(
+            expect(mockLogger.error).toBeCalledTimes(1)
+            expect(mockLogger.error).toHaveBeenCalledWith(
                 'posthog.setPersonProperties was called, but process_person is set to "never". This call will be ignored.'
             )
         })
@@ -593,8 +592,8 @@ describe('person processing', () => {
 
             // assert
             expect(beforeSendMock).toBeCalledTimes(0)
-            expect(jest.mocked(logger).error).toBeCalledTimes(1)
-            expect(jest.mocked(logger).error).toHaveBeenCalledWith(
+            expect(mockLogger.error).toBeCalledTimes(1)
+            expect(mockLogger.error).toHaveBeenCalledWith(
                 'posthog.alias was called, but process_person is set to "never". This call will be ignored.'
             )
         })
@@ -644,7 +643,7 @@ describe('person processing', () => {
 
             // assert
             expect(beforeSendMock).toBeCalledTimes(0)
-            expect(jest.mocked(logger).error).toBeCalledTimes(0)
+            expect(mockLogger.error).toBeCalledTimes(0)
         })
     })
 

src/__tests__/posthog-core.beforeSend.test.ts

@@ -1,11 +1,10 @@
+import { mockLogger } from './helpers/mock-logger'
+
 import { uuidv7 } from '../uuidv7'
 import { defaultPostHog } from './helpers/posthog-instance'
-import { logger } from '../utils/logger'
 import { CaptureResult, knownUnsafeEditableEvent, PostHogConfig } from '../types'
 import { PostHog } from '../posthog-core'
 
-jest.mock('../utils/logger')
-
 const rejectingEventFn = () => {
     return null
 }
@@ -53,9 +52,7 @@ describe('posthog core - before send', () => {
 
         expect(capturedData).toBeUndefined()
         expect(posthog._send_request).not.toHaveBeenCalled()
-        expect(jest.mocked(logger).info).toHaveBeenCalledWith(
-            `Event '${eventName}' was rejected in beforeSend function`
-        )
+        expect(mockLogger.info).toHaveBeenCalledWith(`Event '${eventName}' was rejected in beforeSend function`)
     })
 
     it('can edit an event', () => {
@@ -156,7 +153,7 @@ describe('posthog core - before send', () => {
             method: 'POST',
             url: 'https://us.i.posthog.com/e/',
         })
-        expect(jest.mocked(logger).warn).toHaveBeenCalledWith(
+        expect(mockLogger.warn).toHaveBeenCalledWith(
             `Event '${eventName}' has no properties after beforeSend function, this is likely an error.`
         )
     })
@@ -172,7 +169,7 @@ describe('posthog core - before send', () => {
 
         posthog.capture(randomUnsafeEditableEvent, {}, {})
 
-        expect(jest.mocked(logger).warn).toHaveBeenCalledWith(
+        expect(mockLogger.warn).toHaveBeenCalledWith(
             `Event '${randomUnsafeEditableEvent}' was rejected in beforeSend function. This can cause unexpected behavior.`
         )
     })

src/__tests__/posthog-core.ts

@@ -1,10 +1,11 @@
+import { mockLogger } from './helpers/mock-logger'
+
 import { Info } from '../utils/event-utils'
 import { document, window } from '../utils/globals'
 import { uuidv7 } from '../uuidv7'
 import * as globals from '../utils/globals'
 import { ENABLE_PERSON_PROCESSING, USER_STATE } from '../constants'
 import { createPosthogInstance, defaultPostHog } from './helpers/posthog-instance'
-import { logger } from '../utils/logger'
 import { PostHogConfig, RemoteConfig } from '../types'
 import { PostHog } from '../posthog-core'
 import { PostHogPersistence } from '../posthog-persistence'
@@ -119,24 +120,22 @@ describe('posthog core', () => {
 
             const posthog = posthogWith(defaultConfig, defaultOverrides)
             posthog._addCaptureHook(hook)
-            jest.spyOn(logger, 'error').mockImplementation()
 
             expect(() => posthog.capture(undefined)).not.toThrow()
             expect(hook).not.toHaveBeenCalled()
-            expect(logger.error).toHaveBeenCalledWith('No event name provided to posthog.capture')
+            expect(mockLogger.error).toHaveBeenCalledWith('No event name provided to posthog.capture')
         })
 
         it('errors with object event name', () => {
             const hook = jest.fn()
-            jest.spyOn(logger, 'error').mockImplementation()
 
             const posthog = posthogWith(defaultConfig, defaultOverrides)
             posthog._addCaptureHook(hook)
 
             // @ts-expect-error - testing invalid input
             expect(() => posthog.capture({ event: 'object as name' })).not.toThrow()
             expect(hook).not.toHaveBeenCalled()
-            expect(logger.error).toHaveBeenCalledWith('No event name provided to posthog.capture')
+            expect(mockLogger.error).toHaveBeenCalledWith('No event name provided to posthog.capture')
         })
 
         it('respects opt_out_useragent_filter (default: false)', () => {
@@ -746,8 +745,6 @@ describe('posthog core', () => {
         })
 
         it('does nothing when empty', () => {
-            jest.spyOn(logger, 'warn').mockImplementation()
-
             const posthog = posthogWith({
                 bootstrap: {},
                 persistence: 'memory',
@@ -756,7 +753,7 @@ describe('posthog core', () => {
             expect(posthog.get_distinct_id()).not.toBe('abcd')
             expect(posthog.get_distinct_id()).not.toEqual(undefined)
             expect(posthog.getFeatureFlag('multivariant')).toBe(undefined)
-            expect(logger.warn).toHaveBeenCalledWith(
+            expect(mockLogger.warn).toHaveBeenCalledWith(
                 expect.stringContaining('getFeatureFlag for key "multivariant" failed')
             )
             expect(posthog.getFeatureFlag('disabled')).toBe(undefined)
@@ -902,11 +899,9 @@ describe('posthog core', () => {
 
     describe('skipped init()', () => {
         it('capture() does not throw', () => {
-            jest.spyOn(logger, 'error').mockImplementation()
-
             expect(() => defaultPostHog().capture('$pageview')).not.toThrow()
 
-            expect(logger.error).toHaveBeenCalledWith('You must initialize PostHog before calling posthog.capture')
+            expect(mockLogger.uninitializedWarning).toHaveBeenCalledWith('posthog.capture')
         })
     })
 
@@ -1112,8 +1107,6 @@ describe('posthog core', () => {
         })
 
         it('handles loaded config option throwing gracefully', () => {
-            jest.spyOn(logger, 'critical').mockImplementation()
-
             const posthog = posthogWith(
                 {
                     loaded: () => {
@@ -1133,7 +1126,7 @@ describe('posthog core', () => {
 
             posthog._loaded()
 
-            expect(logger.critical).toHaveBeenCalledWith('`loaded` function failed', expect.anything())
+            expect(mockLogger.critical).toHaveBeenCalledWith('`loaded` function failed', expect.anything())
         })
 
         describe('/decide', () => {