[plugin-server] Always enable console logging to DB (PostHog/plugin-s…

…erver#360) * Enable persistent console always * include all logs for test * include all logs for test * lazy vm test update for plugin logs * more foolproof way to test that this log was in the list * truncate clickhouse logs * wait until we have the event Co-authored-by: Marius Andra <[email protected]>
PostHog · May 7, 2021 · af50795 · af50795
1 parent b4d704e
commit af50795
Show file tree

Hide file tree

Showing 13 changed files with 71 additions and 83 deletions.
diff --git a/src/config/config.ts b/src/config/config.ts
@@ -62,7 +62,6 @@ export function getDefaultConfig(): PluginsServerConfig {
         JOB_QUEUES: '',
         JOB_QUEUE_GRAPHILE_URL: '',
         CRASH_IF_NO_PERSISTENT_JOB_QUEUE: false,
-        ENABLE_PERSISTENT_CONSOLE: false, // TODO: remove when persistent console ships in main repo
         STALENESS_RESTART_SECONDS: 0,
     }
 }

diff --git a/src/types.ts b/src/types.ts
@@ -74,7 +74,6 @@ export interface PluginsServerConfig extends Record<string, any> {
     JOB_QUEUES: string
     JOB_QUEUE_GRAPHILE_URL: string
     CRASH_IF_NO_PERSISTENT_JOB_QUEUE: boolean
-    ENABLE_PERSISTENT_CONSOLE: boolean
     STALENESS_RESTART_SECONDS: number
 }
 

diff --git a/src/utils/db/sql.ts b/src/utils/db/sql.ts
@@ -59,7 +59,7 @@ export async function setError(
         [pluginError, typeof pluginConfig === 'object' ? pluginConfig?.id : pluginConfig],
         'updatePluginConfigError'
     )
-    if (pluginError && server.ENABLE_PERSISTENT_CONSOLE) {
+    if (pluginError) {
         await server.db.createPluginLogEntry(
             pluginConfig,
             PluginLogEntrySource.Plugin,

diff --git a/src/worker/plugins/teardown.ts b/src/worker/plugins/teardown.ts
@@ -13,32 +13,26 @@ export async function teardownPlugins(server: PluginsServer, pluginConfig?: Plug
                     (async () => {
                         try {
                             await teardownPlugin()
-
-                            if (server.ENABLE_PERSISTENT_CONSOLE) {
-                                await server.db.createPluginLogEntry(
-                                    pluginConfig,
-                                    PluginLogEntrySource.System,
-                                    PluginLogEntryType.Info,
-                                    `Plugin unloaded (instance ID ${server.instanceId}).`,
-                                    server.instanceId
-                                )
-                            }
+                            await server.db.createPluginLogEntry(
+                                pluginConfig,
+                                PluginLogEntrySource.System,
+                                PluginLogEntryType.Info,
+                                `Plugin unloaded (instance ID ${server.instanceId}).`,
+                                server.instanceId
+                            )
                         } catch (error) {
                             await processError(server, pluginConfig, error)
-
-                            if (server.ENABLE_PERSISTENT_CONSOLE) {
-                                await server.db.createPluginLogEntry(
-                                    pluginConfig,
-                                    PluginLogEntrySource.System,
-                                    PluginLogEntryType.Error,
-                                    `Plugin failed to unload (instance ID ${server.instanceId}).`,
-                                    server.instanceId
-                                )
-                            }
+                            await server.db.createPluginLogEntry(
+                                pluginConfig,
+                                PluginLogEntrySource.System,
+                                PluginLogEntryType.Error,
+                                `Plugin failed to unload (instance ID ${server.instanceId}).`,
+                                server.instanceId
+                            )
                         }
                     })()
                 )
-            } else if (server.ENABLE_PERSISTENT_CONSOLE) {
+            } else {
                 await server.db.createPluginLogEntry(
                     pluginConfig,
                     PluginLogEntrySource.System,

diff --git a/src/worker/vm/extensions/console.ts b/src/worker/vm/extensions/console.ts
@@ -22,10 +22,6 @@ export function createConsole(server: PluginsServer, pluginConfig: PluginConfig)
             status.info('👉', `${type} in ${pluginDigest(pluginConfig.plugin!, pluginConfig.team_id)}:`, ...args)
         }
 
-        if (!server.ENABLE_PERSISTENT_CONSOLE) {
-            return
-        }
-
         await server.db.createPluginLogEntry(
             pluginConfig,
             PluginLogEntrySource.Console,

diff --git a/src/worker/vm/lazy.ts b/src/worker/vm/lazy.ts
@@ -26,28 +26,24 @@ export class LazyPluginVM {
             ) => {
                 try {
                     const vm = await createPluginConfigVM(server, pluginConfig, indexJs)
-                    if (server.ENABLE_PERSISTENT_CONSOLE) {
-                        await server.db.createPluginLogEntry(
-                            pluginConfig,
-                            PluginLogEntrySource.System,
-                            PluginLogEntryType.Info,
-                            `Plugin loaded (instance ID ${server.instanceId}).`,
-                            server.instanceId
-                        )
-                    }
+                    await server.db.createPluginLogEntry(
+                        pluginConfig,
+                        PluginLogEntrySource.System,
+                        PluginLogEntryType.Info,
+                        `Plugin loaded (instance ID ${server.instanceId}).`,
+                        server.instanceId
+                    )
                     status.info('🔌', `Loaded ${logInfo}`)
                     void clearError(server, pluginConfig)
                     resolve(vm)
                 } catch (error) {
-                    if (server.ENABLE_PERSISTENT_CONSOLE) {
-                        await server.db.createPluginLogEntry(
-                            pluginConfig,
-                            PluginLogEntrySource.System,
-                            PluginLogEntryType.Error,
-                            `Plugin failed to load (instance ID ${server.instanceId}).`,
-                            server.instanceId
-                        )
-                    }
+                    await server.db.createPluginLogEntry(
+                        pluginConfig,
+                        PluginLogEntrySource.System,
+                        PluginLogEntryType.Error,
+                        `Plugin failed to load (instance ID ${server.instanceId}).`,
+                        server.instanceId
+                    )
                     status.warn('⚠️', `Failed to load ${logInfo}`)
                     void processError(server, pluginConfig, error)
                     resolve(null)

diff --git a/tests/clickhouse/e2e.test.ts b/tests/clickhouse/e2e.test.ts
@@ -110,21 +110,17 @@ describe('e2e clickhouse ingestion', () => {
     })
 
     test('console logging is persistent', async () => {
-        if (!server.ENABLE_PERSISTENT_CONSOLE) {
-            // TODO: remove this return
-            return
-        }
-        expect((await server.db.fetchEvents()).length).toBe(0)
+        const logCount = (await server.db.fetchPluginLogEntries()).length
+        const getLogsSinceStart = async () => (await server.db.fetchPluginLogEntries()).slice(logCount)
 
         posthog.capture('custom event', { name: 'hehe', uuid: new UUIDT().toString() })
 
         await server.kafkaProducer?.flush()
-        await delayUntilEventIngested(() => server.db.fetchPluginLogEntries())
-
-        const pluginLogEntries = await server.db.fetchPluginLogEntries()
+        await delayUntilEventIngested(() => server.db.fetchEvents())
 
-        expect(pluginLogEntries.length).toBe(1)
-        expect(pluginLogEntries[0].type).toEqual('INFO')
-        expect(pluginLogEntries[0].message).toEqual('amogus')
+        const pluginLogEntries = await getLogsSinceStart()
+        expect(
+            pluginLogEntries.filter(({ message, type }) => message.includes('amogus') && type === 'INFO').length
+        ).toEqual(1)
     })
 })
diff --git a/tests/helpers/clickhouse.ts b/tests/helpers/clickhouse.ts
@@ -22,4 +22,5 @@ export async function resetTestDatabaseClickhouse(extraServerConfig: Partial<Plu
     await clickhouse.querying('TRUNCATE person_static_cohort')
     await clickhouse.querying('TRUNCATE session_recording_events')
     await clickhouse.querying('TRUNCATE session_recording_events_mv')
+    await clickhouse.querying('TRUNCATE plugin_log_entries')
 }
diff --git a/tests/helpers/sql.ts b/tests/helpers/sql.ts
@@ -37,7 +37,7 @@ export async function resetTestDatabase(
         DELETE FROM posthog_event;
         DELETE FROM posthog_pluginstorage;
         DELETE FROM posthog_pluginattachment;
-        ${config.ENABLE_PERSISTENT_CONSOLE ? 'DELETE FROM posthog_pluginlogentry;' : '' /* TODO: remove this if */}
+        DELETE FROM posthog_pluginlogentry;
         DELETE FROM posthog_pluginconfig;
         DELETE FROM posthog_plugin;
         DELETE FROM posthog_eventdefinition;

diff --git a/tests/postgres/e2e.test.ts b/tests/postgres/e2e.test.ts
@@ -113,21 +113,18 @@ describe('e2e postgres ingestion', () => {
     })
 
     test('console logging is persistent', async () => {
-        if (!server.ENABLE_PERSISTENT_CONSOLE) {
-            // TODO: remove this return
-            return
-        }
-        expect((await server.db.fetchEvents()).length).toBe(0)
+        const logCount = (await server.db.fetchPluginLogEntries()).length
+        const getLogsSinceStart = async () => (await server.db.fetchPluginLogEntries()).slice(logCount)
 
         posthog.capture('custom event', { name: 'hehe', uuid: new UUIDT().toString() })
 
-        await server.kafkaProducer?.flush()
-        await delayUntilEventIngested(() => server.db.fetchPluginLogEntries())
-
-        const pluginLogEntries = await server.db.fetchPluginLogEntries()
+        await delayUntilEventIngested(async () =>
+            (await getLogsSinceStart()).filter(({ message }) => message.includes('amogus'))
+        )
 
-        expect(pluginLogEntries.length).toBe(1)
-        expect(pluginLogEntries[0].type).toEqual('INFO')
-        expect(pluginLogEntries[0].message).toEqual('amogus')
+        const pluginLogEntries = await getLogsSinceStart()
+        expect(
+            pluginLogEntries.filter(({ message, type }) => message.includes('amogus') && type === 'INFO').length
+        ).toEqual(1)
     })
 })
diff --git a/tests/postgres/vm.lazy.test.ts b/tests/postgres/vm.lazy.test.ts
@@ -1,6 +1,6 @@
 import { mocked } from 'ts-jest/utils'
 
-import { PluginTaskType } from '../../src/types'
+import { PluginLogEntrySource, PluginLogEntryType, PluginTaskType } from '../../src/types'
 import { clearError, processError } from '../../src/utils/db/error'
 import { status } from '../../src/utils/status'
 import { LazyPluginVM } from '../../src/worker/vm/lazy'
@@ -12,8 +12,12 @@ jest.mock('../../src/utils/status')
 
 describe('LazyPluginVM', () => {
     const createVM = () => new LazyPluginVM()
-    const initializeVm = (vm: LazyPluginVM) =>
-        vm.initialize!('mockServer' as any, 'mockConfig' as any, '', 'some plugin')
+    const mockServer: any = {
+        db: {
+            createPluginLogEntry: jest.fn(),
+        },
+    }
+    const initializeVm = (vm: LazyPluginVM) => vm.initialize!(mockServer, 'mockConfig' as any, '', 'some plugin')
 
     describe('VM creation succeeds', () => {
         const mockVM = {
@@ -49,7 +53,14 @@ describe('LazyPluginVM', () => {
             await vm.resolveInternalVm
 
             expect(status.info).toHaveBeenCalledWith('🔌', 'Loaded some plugin')
-            expect(clearError).toHaveBeenCalledWith('mockServer', 'mockConfig')
+            expect(clearError).toHaveBeenCalledWith(mockServer, 'mockConfig')
+            expect(mockServer.db.createPluginLogEntry).toHaveBeenCalledWith(
+                'mockConfig',
+                PluginLogEntrySource.System,
+                PluginLogEntryType.Info,
+                expect.stringContaining('Plugin loaded'),
+                undefined
+            )
         })
     })
 
@@ -78,7 +89,14 @@ describe('LazyPluginVM', () => {
             } catch {}
 
             expect(status.warn).toHaveBeenCalledWith('⚠️', 'Failed to load some plugin')
-            expect(processError).toHaveBeenCalledWith('mockServer', 'mockConfig', error)
+            expect(processError).toHaveBeenCalledWith(mockServer, 'mockConfig', error)
+            expect(mockServer.db.createPluginLogEntry).toHaveBeenCalledWith(
+                'mockConfig',
+                PluginLogEntrySource.System,
+                PluginLogEntryType.Error,
+                expect.stringContaining('Plugin failed to load'),
+                undefined
+            )
         })
     })
 })
diff --git a/tests/postgres/vm.test.ts b/tests/postgres/vm.test.ts
@@ -585,10 +585,6 @@ test('meta.cache incr', async () => {
 })
 
 test('console.log', async () => {
-    if (!mockServer.ENABLE_PERSISTENT_CONSOLE) {
-        // TODO: remove this return
-        return
-    }
     jest.spyOn(mockServer.db, 'createPluginLogEntry')
 
     const indexJs = `

diff --git a/tests/worker/console.test.ts b/tests/worker/console.test.ts
@@ -22,10 +22,6 @@ describe('console extension', () => {
     Object.values(PluginLogEntryType).map((type) => {
         const method = type.toLowerCase() as keyof ConsoleExtension
         describe(`console#${method}`, () => {
-            if (!server.ENABLE_PERSISTENT_CONSOLE) {
-                // TODO: remove this return
-                return
-            }
             it('leaves an empty entry in the database', async () => {
                 const pluginConfig = (await getPluginConfigRows(server))[0]