Repository: PostHog/posthog
Pull request: Plugin log entries
## Changes

This is ~~a proposed~~ the accepted and awaiting complete implementation in this PR (and a complimentary one in https://github.com/PostHog/plugin-server) data model to resolve PostHog/plugin-server#72.
The unit of plugin logging is a single plugin log entry (`PluginLogEntry` model for Postgres and a schema-wise drop-in equivalent `plugin_log_entries` topic → `kafka_plugin_log_entries` table → `plugin_log_entries` table setup in Kafka+ClickHouse).

This looks like some complexity at first, but it's straightforward compared to fighting Postgres's scale limitations:

- For FOSS users, the solution is the simplest possible plain `INSERT`s/`SELECT`s on `posthog_pluginlogentry`, and we know they won't have problems with scale.
- For Cloud/EE, we need to support LARGE scale with minimum maintenance and high data integrity. For this part Kafka+ClickHouse is unbeatable within our existing infrastructure. And also very simple "produce to topic on every `console` method call in plugin server, `SELECT` relevant entries from table in Django server".

Kafka+ClickHouse parts adapted from session recording events handling, which is similarly simple (though actually logs are far better for this infrastructure than session recording, which is too storage space-intensive).

Problem statement:
Stream console.log output somewhere
To improve the dev experience, running `console.log` (and `.info`, etc) inside the plugin should send this information somewhere.

First thoughts:
- Do ``console.log = (...args) => (posthog.capture(`${pluginName} console.log`, { args })``? Too easy to endlessly loop...
- Something on `plugin_config` in postgres? Too high throughput...
- Redis?
- Kafka?
- Custom nodejs logger service that remembers the last 100 console.log messages per plugin and just periodically flushes the last state to postgres? How to thandle multithreading and multiple worker instances?
- ???

Hints from issue discussion:
TBH Kafka or ClickHouse would be best (in practice just Kafka would do)… But that's EE only.
The problem we're trying to solve is twofold:
1) A lot of noise in the server logs from random plugins that adds little value
2) It might be useful to see the console logs in the interface, to check how your plugin is doing (e.g. when did it last sync, etc)

Here's a rough proposal to capture/stream logs without introducing any new technologies:

- Create a new postgres model `PluginConfigLog(plugin_config_id: number, plugin_server_instance_random_unique_id: string, log: jsonb[])`, where `log = { time: 'ISO', type: 'info', message: 'bla' }[]`
- In each plugin server instance, in each VM, have the `console.*` methods save the last `N = 250` lines (and/or last `T0 = 48h`?) of the log in a simple buffer (array?)
- Every `T1 = 10 seconds`, if needed, `upsert` the entire buffer of `N` lines into the `PluginConfigLog` row (one row per plugin per server instance), discarding all the log entries that were there before
- In the frontend, have a super simple log viewer that selects all the relevant `PluginConfigLog`s for this plugin and merges the `log` lines together... or even shows them per server if needed
- Have a cleanup script that periodically deletes all rows older than `T0`.

Could this work and be simple enough? Or is this over-engineering?

I'd like to avoid writing a new row into postgres per `console.log` call, as I fear that a nasty plugin that runs thousands of times per second will cause too much unnecessary I/O. This way if there's anything to write, the amount that we write is controlled (at most `N = 250` times `~100 bytes per line` = `25kb` per insert/update).
This would definitely work, though sounds kind of dirty… Lots of data handholding to ensure reasonable integrity.
I guess we can't make logs a Cloud/EE feature? Kafka+ClickHouse is a pretty great solution for logs of almost unlimited scale…
I think we should still have some basic logs on OSS as well. So I'd start with writing something very basic and if needed, we can develop a good EE logging solution after.

Commit message: Add migration

Patch to review:
diff --git a/ee/clickhouse/migrations/0008_plugin_log_entries.py b/ee/clickhouse/migrations/0008_plugin_log_entries.py
new file mode 100644
index 0000000000000..0fb4b39cf61d1
--- /dev/null
+++ b/ee/clickhouse/migrations/0008_plugin_log_entries.py
@@ -0,0 +1,13 @@
+from infi.clickhouse_orm import migrations
+
+from ee.clickhouse.sql.plugin_log_entries import (
+    KAFKA_PLUGIN_LOG_ENTRIES_TABLE_SQL,
+    PLUGIN_LOG_ENTRIES_TABLE_MV_SQL,
+    PLUGIN_LOG_ENTRIES_TABLE_SQL,
+)
+
+operations = [
+    migrations.RunSQL(PLUGIN_LOG_ENTRIES_TABLE_SQL),
+    migrations.RunSQL(KAFKA_PLUGIN_LOG_ENTRIES_TABLE_SQL),
+    migrations.RunSQL(PLUGIN_LOG_ENTRIES_TABLE_MV_SQL),
+]
diff --git a/ee/clickhouse/sql/plugin_log_entries.py b/ee/clickhouse/sql/plugin_log_entries.py
new file mode 100644
index 0000000000000..6374c4059689a
--- /dev/null
+++ b/ee/clickhouse/sql/plugin_log_entries.py
@@ -0,0 +1,62 @@
+from ee.kafka_client.topics import KAFKA_PLUGIN_LOG_ENTRIES
+
+from .clickhouse import KAFKA_COLUMNS, kafka_engine, table_engine, ttl_period
+
+PLUGIN_LOG_ENTRIES_TABLE = "plugin_log_entries"
+
+PLUGIN_LOG_ENTRIES_TABLE_BASE_SQL = """
+CREATE TABLE {table_name}
+(
+    id UUID,
+    team_id Int64,
+    plugin_id Int64,
+    timestamp DateTime64(6, 'UTC'),
+    type VARCHAR,
+    message VARCHAR
+    {extra_fields}
+) ENGINE = {engine}
+"""
+
+PLUGIN_LOG_ENTRIES_TABLE_SQL = (
+    PLUGIN_LOG_ENTRIES_TABLE_BASE_SQL
+    + """PARTITION BY toYYYYMMDD(timestamp)
+ORDER BY (team_id, toHour(timestamp), plugin_id, timestamp, id)
+{ttl_period}
+SETTINGS index_granularity=512
+"""
+).format(
+    table_name=PLUGIN_LOG_ENTRIES_TABLE,
+    extra_fields=KAFKA_COLUMNS,
+    engine=table_engine(PLUGIN_LOG_ENTRIES_TABLE, "_timestamp"),
+    ttl_period=ttl_period(),
+)
+
+KAFKA_PLUGIN_LOG_ENTRIES_TABLE_SQL = PLUGIN_LOG_ENTRIES_TABLE_BASE_SQL.format(
+    table_name="kafka_" + PLUGIN_LOG_ENTRIES_TABLE,
+    engine=kafka_engine(topic=KAFKA_PLUGIN_LOG_ENTRIES),
+    extra_fields="",
+)
+
+PLUGIN_LOG_ENTRIES_TABLE_MV_SQL = """
+CREATE MATERIALIZED VIEW {table_name}_mv
+TO {table_name}
+AS SELECT
+id,
+team_id,
+plugin_id,
+timestamp,
+type,
+message,
+_timestamp,
+_offset
+FROM kafka_{table_name}
+""".format(
+    table_name=PLUGIN_LOG_ENTRIES_TABLE
+)
+
+
+INSERT_PLUGIN_LOG_ENTRY_SQL = """
+INSERT INTO plugin_log_entries SELECT %(id)s, %(team_id)s, %(plugin_id)s, %(timestamp)s, %(type)s, %(message)s, now(), 0
+"""
+
+DROP_PLUGIN_LOG_ENTRIES_TABLE_SQL = "DROP TABLE plugin_log_entries"
diff --git a/ee/kafka_client/topics.py b/ee/kafka_client/topics.py
index 97ac9ad1f5321..3b3e6cbf02e54 100644
--- a/ee/kafka_client/topics.py
+++ b/ee/kafka_client/topics.py
@@ -4,3 +4,4 @@
 KAFKA_SESSION_RECORDING_EVENTS = "clickhouse_session_recording_events"
 KAFKA_EVENTS_WAL = "events_write_ahead_log"
 KAFKA_EVENTS_PLUGIN_INGESTION = "events_plugin_ingestion"
+KAFKA_PLUGIN_LOG_ENTRIES = "plugin_log_entries"
diff --git a/latest_migrations.manifest b/latest_migrations.manifest
index bfe392097e0ff..79723d0f403ed 100644
--- a/latest_migrations.manifest
+++ b/latest_migrations.manifest
@@ -3,7 +3,7 @@ auth: 0011_update_proxy_permissions
 axes: 0006_remove_accesslog_trusted
 contenttypes: 0002_remove_content_type_name
 ee: 0002_hook
-posthog: 0129_merge_20210223_0757
+posthog: 0130_pluginlogentry
 rest_hooks: 0002_swappable_hook_model
 sessions: 0001_initial
 social_django: 0008_partial_timestamp
diff --git a/posthog/migrations/0130_pluginlogentry.py b/posthog/migrations/0130_pluginlogentry.py
new file mode 100644
index 0000000000000..5da424fc272ed
--- /dev/null
+++ b/posthog/migrations/0130_pluginlogentry.py
@@ -0,0 +1,37 @@
+# Generated by Django 3.0.6 on 2021-02-25 13:53
+
+import django.db.models.deletion
+import django.utils.timezone
+from django.db import migrations, models
+
+import posthog.models.utils
+
+
+class Migration(migrations.Migration):
+
+    dependencies = [
+        ("posthog", "0129_merge_20210223_0757"),
+    ]
+
+    operations = [
+        migrations.CreateModel(
+            name="PluginLogEntry",
+            fields=[
+                (
+                    "id",
+                    models.UUIDField(
+                        default=posthog.models.utils.UUIDT, editable=False, primary_key=True, serialize=False
+                    ),
+                ),
+                ("timestamp", models.DateTimeField(default=django.utils.timezone.now)),
+                (
+                    "type",
+                    models.CharField(choices=[("INFO", "info"), ("WARN", "warn"), ("ERROR", "error")], max_length=20),
+                ),
+                ("message", models.CharField(max_length=500)),
+                ("plugin", models.ForeignKey(on_delete=django.db.models.deletion.CASCADE, to="posthog.Plugin")),
+                ("team", models.ForeignKey(null=True, on_delete=django.db.models.deletion.CASCADE, to="posthog.Team")),
+            ],
+            options={"abstract": False,},
+        ),
+    ]
diff --git a/posthog/models/plugin.py b/posthog/models/plugin.py
index 340acbe4525fd..d0fd09275dcf6 100644
--- a/posthog/models/plugin.py
+++ b/posthog/models/plugin.py
@@ -1,5 +1,8 @@
 from django.contrib.postgres.fields import JSONField
 from django.db import models
+from django.utils import timezone
+
+from .utils import UUIDModel, sane_repr
 
 
 class Plugin(models.Model):
@@ -64,3 +67,21 @@ class Meta:
     plugin_config: models.ForeignKey = models.ForeignKey("PluginConfig", on_delete=models.CASCADE)
     key: models.CharField = models.CharField(max_length=200)
     value: models.TextField = models.TextField(blank=True, null=True)
+
+
+class PluginLogEntry(UUIDModel):
+    class Type(models.TextChoices):
+        INFO = "INFO", "info"
+        WARN = "WARN", "warn"
+        ERROR = "ERROR", "error"
+
+    team: models.ForeignKey = models.ForeignKey("Team", on_delete=models.CASCADE, null=True)
+    plugin: models.ForeignKey = models.ForeignKey("Plugin", on_delete=models.CASCADE)
+    timestamp: models.DateTimeField = models.DateTimeField(default=timezone.now)
+    type: models.CharField = models.CharField(max_length=20, choices=Type.choices)
+    message: models.CharField = models.CharField(max_length=500)
+
+    def __str__(self):
+        return f"[{self.timestamp.isoformat()}] {self.type}: {self.message}"
+
+    __repr__ = sane_repr("team_id", "plugin_id", "timestamp", "type", "message")


Code review comments:
diff_hunk: @@ -64,3 +67,21 @@ class Meta:
     plugin_config: models.ForeignKey = models.ForeignKey("PluginConfig", on_delete=models.CASCADE)
     key: models.CharField = models.CharField(max_length=200)
     value: models.TextField = models.TextField(blank=True, null=True)
+
+
+class PluginLogEntry(UUIDModel):
+    class Type(models.TextChoices):
+        INFO = "INFO", "info"
+        WARN = "WARN", "warn"
+        ERROR = "ERROR", "error"
+
+    team: models.ForeignKey = models.ForeignKey("Team", on_delete=models.CASCADE, null=True)
+    plugin: models.ForeignKey = models.ForeignKey("Plugin", on_delete=models.CASCADE)
+    timestamp: models.DateTimeField = models.DateTimeField(default=timezone.now)
+    type: models.CharField = models.CharField(max_length=20, choices=Type.choices)
+    message: models.CharField = models.CharField(max_length=500)
path: posthog/models/plugin.py
text: @user1:
is the 500 char limit reasonable? It could be a textfield perhaps?

@author:
Done.