Live fetch error due to max_offset being set to 0_0

[robacourt]

Here you can see the logging of the fetch and the error message:

[info] Query String: cursor=4289660&database_id=e32829e3-8111-4e32-9ff3-44362712b58e&handle=94444711-1732664312344&live=true&offset=118147440_0&table=users
15:35:09.406 [error] ** (Plug.Conn.WrapperError) ** (FunctionClauseError) no function clause matching in Electric.ShapeCache.Storage.get_log_stream/3
(electric 0.9.3) lib/electric/shape_cache/storage.ex:176: Electric.ShapeCache.Storage.get_log_stream(LogOffset.new(118147440, 0), LogOffset.new(0, 0), {Electric.ShapeCache.FileStorage, %Electric.ShapeCache.FileStorage{base_path: "/mnt/efs/./shapes/e32829e3-8111-4e32-9ff3-44362712b58e", shape_handle: "94444711-1732664312344", db: {:via, Registry, {:"Elixir.Electric.ProcessRegistry:e32829e3-8111-4e32-9ff3-44362712b58e", {Electric.ShapeCache.FileStorage, "94444711-1732664312344"}}}, cubdb_dir: "/mnt/efs/./shapes/e32829e3-8111-4e32-9ff3-44362712b58e/94444711-1732664312344/cubdb", shape_definition_dir: "/mnt/efs/./shapes/e32829e3-8111-4e32-9ff3-44362712b58e/94444711-1732664312344", snapshot_dir: "/mnt/efs/./shapes/e32829e3-8111-4e32-9ff3-44362712b58e/94444711-1732664312344/snapshots", stack_id: "e32829e3-8111-4e32-9ff3-44362712b58e", extra_opts: %{}, version: 2}})
(electric 0.9.3) lib/electric/plug/serve_shape_plug.ex:468: Electric.Plug.ServeShapePlug.serve_shape_log/1
(opentelemetry 1.5.0) /app/deps/opentelemetry/src/otel_tracer_default.erl:47: :otel_tracer_default.with_span/5
(electric 0.9.3) lib/electric/telemetry/open_telemetry.ex:67: anonymous fn/3 in Electric.Telemetry.OpenTelemetry.with_span/3
(telemetry 1.3.0) /app/deps/telemetry/src/telemetry.erl:324: :telemetry.span/3
(electric 0.9.3) lib/electric/plug/serve_shape_plug.ex:1: Electric.Plug.ServeShapePlug.plug_builder_call/2
(electric 0.9.3) /app/deps/plug/lib/plug/error_handler.ex:80: Electric.Plug.ServeShapePlug.call/2
(cloud_electric 0.1.0) deps/plug/lib/plug/router.ex:246: anonymous fn/4 in CloudElectric.Plugs.PerTenantRouter.dispatch/2

The FunctionClauseError is being raised because of a guard on the function that prohibits the max_offset from being under the offset but for some reason the max_offset is being set to LogOffset.new(0, 0).

max_offset is calculated in the ServeShapePlug using the chunking algorithm, so it looks like there might be an issue there.

At this point I do not know under what scenarios this occurs.

[kevin-dp]

I managed to reproduce this error. It occurs when we make a shape request to an existing shape with an existing handle and the shape has no changes in its log (i.e. its last offset is still 0_0) but our shape request provides an offset that is bigger than 0_0 (and is obviously wrong).

Steps to reproduce

Start Electric

$ iex -S mix

Create a table in Postgres:

CREATE TABLE test (a INT);

Now make an initial shape request (i'm using HTTPie here):

$ HTTP GET localhost:3000/v1/shape table==test offset==-1
HTTP/1.1 200 OK
access-control-allow-methods: GET, HEAD, DELETE, OPTIONS
access-control-allow-origin: *
access-control-expose-headers: *
cache-control: public, max-age=604800, s-maxage=3600, stale-while-revalidate=2629746
content-type: application/json; charset=utf-8
date: Tue, 03 Dec 2024 13:19:06 GMT
electric-handle: 33627585-1733231947475
electric-offset: 0_0
electric-schema: {"a":{"type":"int4"}}
etag: 33627585-1733231947475:-1:0_0
server: ElectricSQL/0.9.0
transfer-encoding: chunked
x-request-id: GA2tRe4QvKlDpzwAAABj

[]

Now make a follow up request that includes the correct handle but a wrong offset:

$ HTTP GET localhost:3000/v1/shape table==test offset==118147440_0 handle==33627585-1733231947475
HTTP/1.1 500 Internal Server Error

And if we look at the logs in Electric:

14:19:58.785 [error] ** (Plug.Conn.WrapperError) ** (FunctionClauseError) no function clause matching in Electric.ShapeCache.Storage.get_log_stream/3
    (electric 0.9.3) lib/electric/shape_cache/storage.ex:184: Electric.ShapeCache.Storage.get_log_stream(LogOffset.new(118147440, 0), LogOffset.new(0, 0), {Electric.ShapeCache.FileStorage, %Electric.ShapeCache.FileStorage{base_path: "./persistent/./shapes/single_stack", shape_handle: "33627585-1733231947475", db: {:via, Registry, {:"Elixir.Electric.ProcessRegistry:single_stack", {Electric.ShapeCache.FileStorage, "33627585-1733231947475"}}}, data_dir: "./persistent/./shapes/single_stack/33627585-1733231947475", cubdb_dir: "./persistent/./shapes/single_stack/33627585-1733231947475/cubdb", snapshot_dir: "./persistent/./shapes/single_stack/33627585-1733231947475/snapshots", stack_id: "single_stack", extra_opts: %{}, version: 2}})
    (electric 0.9.3) lib/electric/plug/serve_shape_plug.ex:468: Electric.Plug.ServeShapePlug.serve_shape_log/1
    (opentelemetry 1.5.0) /Users/kevin/Documents/Electric/development/electric/packages/sync-service/deps/opentelemetry/src/otel_tracer_default.erl:47: :otel_tracer_default.with_span/5
    (electric 0.9.3) lib/electric/telemetry/open_telemetry.ex:68: anonymous fn/3 in Electric.Telemetry.OpenTelemetry.with_span/3
    (telemetry 1.2.1) /Users/kevin/Documents/Electric/development/electric/packages/sync-service/deps/telemetry/src/telemetry.erl:321: :telemetry.span/3
    (electric 0.9.3) lib/electric/plug/serve_shape_plug.ex:1: Electric.Plug.ServeShapePlug.plug_builder_call/2
    (electric 0.9.3) deps/plug/lib/plug/error_handler.ex:80: Electric.Plug.ServeShapePlug.call/2
    (electric 0.9.3) deps/plug/lib/plug/router.ex:246: anonymous fn/4 in Electric.Plug.Router.dispatch/2
    (telemetry 1.2.1) /Users/kevin/Documents/Electric/development/electric/packages/sync-service/deps/telemetry/src/telemetry.erl:321: :telemetry.span/3
    (electric 0.9.3) deps/plug/lib/plug/router.ex:242: Electric.Plug.Router.dispatch/2
    (electric 0.9.3) lib/electric/plug/router.ex:1: Electric.Plug.Router.plug_builder_call/2
    (bandit 1.5.5) lib/bandit/pipeline.ex:124: Bandit.Pipeline.call_plug!/2
    (bandit 1.5.5) lib/bandit/pipeline.ex:36: Bandit.Pipeline.run/4
    (bandit 1.5.5) lib/bandit/http1/handler.ex:12: Bandit.HTTP1.Handler.handle_data/3
    (bandit 1.5.5) lib/bandit/delegating_handler.ex:18: Bandit.DelegatingHandler.handle_data/3
    (bandit 1.5.5) /Users/kevin/Documents/Electric/development/electric/packages/sync-service/deps/thousand_island/lib/thousand_island/handler.ex:411: Bandit.DelegatingHandler.handle_continue/2
    (stdlib 6.0.1) gen_server.erl:2163: :gen_server.try_handle_continue/3
    (stdlib 6.0.1) gen_server.erl:2072: :gen_server.loop/7
    (stdlib 6.0.1) proc_lib.erl:329: :proc_lib.init_p_do_apply/3

Solution

The solution consists of making an explicit check in the serve shape plug to check that the provided offset isn't bigger than the last offset for that shape. I'm currently implementing that.