Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

fluree/server hanging on transaction requests after large request #948

Open
jdorety opened this issue Jan 8, 2025 · 2 comments
Open

fluree/server hanging on transaction requests after large request #948

jdorety opened this issue Jan 8, 2025 · 2 comments
Labels
bug Something isn't working as expected

Comments

@jdorety
Copy link

jdorety commented Jan 8, 2025 •
edited
Loading

Using Docker image tagged fluree/server:5839ffe273062b8da972b120deb54dd62e7c3d1f

The series of transactions contained in test-txs.zip appears to have placed my nexus-app ledger in a state where it will not complete subsequent transactions in a timely manner (if at all?)
Nodes in the ledger do appear to have been created from the requests, as illustrated in the below series of snippets.

TX request body:

{
    "ledger": "nexus-app",
    "insert": [{
        "@id": "gleep",
        "message": "glorp"
    }]
}

Eventual response:

{
    "error": "db/response-timeout",
    "message": "Timeout waiting for transaction to complete for: nexus-app with tx-id: 29cdaceb0a06395ae1b784eba810aa2f4ed7010ea5e0b45b968d24a91f06e3db"
}

Query:

{
    "@context": {
        "f": "https://ns.flur.ee/ledger#",
        "rdf": "http://www.w3.org/1999/02/22-rdf-syntax-ns#",
        "rdfs": "http://www.w3.org/2000/01/rdf-schema#",
        "schema": "http://schema.org/",
        "owl": "http://www.w3.org/2002/07/owl#",
        "sh": "http://www.w3.org/ns/shacl#",
        "skos": "http://www.w3.org/2008/05/skos#",
        "xsd": "http://www.w3.org/2001/XMLSchema#",
        "ex": "http://example.org/",
        "id": "@id",
        "type": "@type",
        "accounts": {
            "@reverse": "userId"
        }
    },
    "select": {
        "gleep": ["*"]
    },
    "from": "nexus-app"
}

returns this response

[
    {
        "id": "gleep"
    }
]

FWIW, I attempted this query: this doesn't work like I thought it did

{
  "select": {
          "?l": ["*"]
      },
      "where": {
          "id": "?l",
          "tx-id": "29cdaceb0a06395ae1b784eba810aa2f4ed7010ea5e0b45b968d24a91f06e3db"
      },
      "from": "nexus-app"
}

and received [] in response

Here's the relevant(?) transaction record data

[
    {
        "f:alias": "nexus-app",
        "f:time": 1736359868733,
        "f:txn": "fluree:file://nexus-app/txn/29cdaceb0a06395ae1b784eba810aa2f4ed7010ea5e0b45b968d24a91f06e3db.json",
        "f:previous": {
            "id": "fluree:commit:sha256:bbviwrrw4ry3wppjriz27zso32q2qcy36qglc3czbubaeohatqb6x"
        },
        "id": "fluree:commit:sha256:bbghbw5ixtnfwrhh6zwd7oi7yqxhsgv3xzkcthsex77tdnp33ech4",
        "f:v": 1,
        "f:branch": "main",
        "f:address": "fluree:file://nexus-app/commit/0fd799482171b8bfb1612f813ac8c0b7b82fde300c207310528ae326dd23690f.json",
        "f:data": {
            "f:address": "fluree:file://nexus-app/commit/4f2a62ac14611c9adb855d607b06bdcbf0af11d4a64dc5fbcfccdc3ab187487b.json",
            "f:flakes": 69634,
            "f:previous": {
                "id": "fluree:db:sha256:bbpl63mkmfkujh2pury7dz4hlpmd2lzuidjrtelpxfslsvqxfen64"
            },
            "f:size": 61218813,
            "f:t": 4,
            "id": "fluree:db:sha256:bt5jau735tolbjmz5bntvpbqiz3uonrxnlmounwm5nestgflsoyb"
        }
    }
]
@jdorety jdorety added the bug Something isn't working as expected label Jan 8, 2025
@jdorety
Copy link
Author

jdorety commented Jan 8, 2025

Here are the logs associated w/ the above transaction example ☝

17:18:01.100 [async-dispatch-3] ERROR fluree.server.consensus.standalone - Unexpected event message - expected two-tuple of [event-type event-data],  and of a supported event type. Received: [:tx-queue {:txn {"https://ns.flur.ee/ledger#insert" [{"@value" [{"message" "glorp", "@id" "gleep"}], "@type" "@json"}], "https://ns.flur.ee/ledger#ledger" [{"@value" "nexus-app"}]}, :size 2, :tx-id "29cdaceb0a06395ae1b784eba810aa2f4ed7010ea5e0b45b968d24a91f06e3db", :ledger-id "nexus-app", :opts {:context nil, :raw-txn {"insert" [{"message" "glorp", "@id" "gleep"}], "ledger" "nexus-app"}}, :instant 1736356681095}] #error {
 :cause "Additional data must be non-nil."
 :via
 [{:type java.lang.IllegalArgumentException
   :message "Additional data must be non-nil."
   :at [clojure.lang.ExceptionInfo <init> "ExceptionInfo.java" 31]}]
 :trace
 [[clojure.lang.ExceptionInfo <init> "ExceptionInfo.java" 31]
  [clojure.lang.ExceptionInfo <init> "ExceptionInfo.java" 22]
  [clojure.core$ex_info invokeStatic "core.clj" 4808]
  [clojure.core$ex_info invoke "core.clj" 4808]
  [fluree.server.consensus.broadcast$announce_error_BANG_ invokeStatic "broadcast.clj" 31]
  [fluree.server.consensus.broadcast$announce_error_BANG_ invoke "broadcast.clj" 27]
  [fluree.server.consensus.standalone$process_event$fn__64834$state_machine__5949__auto____64843$fn__64846 invoke "standalone.clj" 75]
  [fluree.server.consensus.standalone$process_event$fn__64834$state_machine__5949__auto____64843 invoke "standalone.clj" 66]
  [clojure.core.async.impl.ioc_macros$run_state_machine invokeStatic "ioc_macros.clj" 972]
  [clojure.core.async.impl.ioc_macros$run_state_machine invoke "ioc_macros.clj" 971]
  [clojure.core.async.impl.ioc_macros$run_state_machine_wrapped invokeStatic "ioc_macros.clj" 976]
  [clojure.core.async.impl.ioc_macros$run_state_machine_wrapped invoke "ioc_macros.clj" 974]
  [clojure.core.async.impl.ioc_macros$take_BANG_$fn__5967 invoke "ioc_macros.clj" 985]
  [clojure.core.async.impl.channels.ManyToManyChannel$fn__786$fn__787 invoke "channels.clj" 100]
  [clojure.lang.AFn run "AFn.java" 22]
  [java.util.concurrent.ThreadPoolExecutor runWorker nil -1]
  [java.util.concurrent.ThreadPoolExecutor$Worker run nil -1]
  [clojure.core.async.impl.concurrent$counted_thread_factory$reify__689$fn__690 invoke "concurrent.clj" 29]
  [clojure.lang.AFn run "AFn.java" 22]
  [java.lang.Thread run nil -1]]}
eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:969)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1194)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1149)
	at java.base/java.lang.Thread.run(Unknown Source)
2025-01-08T15:39:39.493573291Z :post "/fluree/transact" => Error in ledger handler
clojure.lang.ExceptionInfo: Error in ledger handler {:response {:status 408, :body {:error :db/response-timeout, :message "Timeout waiting for transaction to complete for: nexus-app with tx-id: 4986ace88fbdacb9e4ddb6b3af1f8db88b1e66894eac5fa791ae953f75014fff"}}}
	at fluree.server.handlers.transact$default.invokeStatic(transact.clj:82)
	at fluree.server.handlers.transact$default.invoke(transact.clj:82)
	at clojure.lang.Var.invoke(Var.java:384)
	at reitit.ring.middleware.exception$wrap$fn__69543$fn__69544.invoke(exception.clj:49)
	at fluree.server.handler$wrap_closed_mode$fn__69937$fn__69939.invoke(handler.clj:238)
	at fluree.server.handler$wrap_policy_metadata$fn__69949.invoke(handler.clj:273)
	at reitit.ring.coercion$fn__69483$fn__69485$fn__69486.invoke(coercion.cljc:40)
	at reitit.ring.coercion$fn__69494$fn__69496$fn__69497.invoke(coercion.cljc:64)
	at reitit.ring.coercion$fn__69507$fn__69509$fn__69510.invoke(coercion.cljc:80)
	at fluree.server.handler$wrap_set_fuel_header$fn__69946.invoke(handler.clj:243)
	at fluree.server.handler$unwrap_credential$fn__69922.invoke(handler.clj:212)
	at fluree.server.handler$wrap_assoc_system$fn__69917.invoke(handler.clj:174)
	at ring.middleware.cors$handle_cors.invokeStatic(cors.cljc:178)
	at ring.middleware.cors$handle_cors.invoke(cors.cljc:167)
	at ring.middleware.cors$wrap_cors$fn__69902.invoke(cors.cljc:205)
	at reitit.ring.middleware.exception$wrap$fn__69543$fn__69544.invoke(exception.clj:49)
	at muuntaja.middleware$wrap_format_request$fn__69597.invoke(middleware.clj:114)
	at muuntaja.middleware$wrap_format_response$fn__69601.invoke(middleware.clj:132)
	at muuntaja.middleware$wrap_format_negotiate$fn__69594.invoke(middleware.clj:96)
	at reitit.ring$ring_handler$fn__69338.invoke(ring.cljc:357)
	at clojure.lang.AFn.applyToHelper(AFn.java:154)
	at clojure.lang.AFn.applyTo(AFn.java:144)
	at clojure.lang.AFunction$1.doInvoke(AFunction.java:31)
	at clojure.lang.RestFn.invoke(RestFn.java:408)
	at ring.adapter.jetty9.handlers.sync$_doHandle.invokeStatic(sync.clj:30)
	at ring.adapter.jetty9.handlers.sync$_doHandle.invoke(sync.clj:21)
	at ring.adapter.jetty9.handlers.SyncProxyHandler.doHandle(Unknown Source)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:221)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1381)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:176)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:484)
	at ring.adapter.jetty9.handlers.SyncProxyHandler.doScope(Unknown Source)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:174)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1303)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:129)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
	at org.eclipse.jetty.server.Server.handle(Server.java:563)
	at org.eclipse.jetty.server.HttpChannel$RequestDispatchable.dispatch(HttpChannel.java:1598)
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:753)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:501)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:287)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:314)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)
	at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:969)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1194)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1149)
	at java.base/java.lang.Thread.run(Unknown Source)
2025-01-08T17:20:01.101973673Z :post "/fluree/transact" => Error in ledger handler
clojure.lang.ExceptionInfo: Error in ledger handler {:response {:status 408, :body {:error :db/response-timeout, :message "Timeout waiting for transaction to complete for: nexus-app with tx-id: 29cdaceb0a06395ae1b784eba810aa2f4ed7010ea5e0b45b968d24a91f06e3db"}}}
	at fluree.server.handlers.transact$default.invokeStatic(transact.clj:82)
	at fluree.server.handlers.transact$default.invoke(transact.clj:82)
	at clojure.lang.Var.invoke(Var.java:384)
	at reitit.ring.middleware.exception$wrap$fn__69543$fn__69544.invoke(exception.clj:49)
	at fluree.server.handler$wrap_closed_mode$fn__69937$fn__69939.invoke(handler.clj:238)
	at fluree.server.handler$wrap_policy_metadata$fn__69949.invoke(handler.clj:273)
	at reitit.ring.coercion$fn__69483$fn__69485$fn__69486.invoke(coercion.cljc:40)
	at reitit.ring.coercion$fn__69494$fn__69496$fn__69497.invoke(coercion.cljc:64)
	at reitit.ring.coercion$fn__69507$fn__69509$fn__69510.invoke(coercion.cljc:80)
	at fluree.server.handler$wrap_set_fuel_header$fn__69946.invoke(handler.clj:243)
	at fluree.server.handler$unwrap_credential$fn__69922.invoke(handler.clj:212)
	at fluree.server.handler$wrap_assoc_system$fn__69917.invoke(handler.clj:174)
	at ring.middleware.cors$handle_cors.invokeStatic(cors.cljc:178)
	at ring.middleware.cors$handle_cors.invoke(cors.cljc:167)
	at ring.middleware.cors$wrap_cors$fn__69902.invoke(cors.cljc:205)
	at reitit.ring.middleware.exception$wrap$fn__69543$fn__69544.invoke(exception.clj:49)
	at muuntaja.middleware$wrap_format_request$fn__69597.invoke(middleware.clj:114)
	at muuntaja.middleware$wrap_format_response$fn__69601.invoke(middleware.clj:132)
	at muuntaja.middleware$wrap_format_negotiate$fn__69594.invoke(middleware.clj:96)
	at reitit.ring$ring_handler$fn__69338.invoke(ring.cljc:357)
	at clojure.lang.AFn.applyToHelper(AFn.java:154)
	at clojure.lang.AFn.applyTo(AFn.java:144)
	at clojure.lang.AFunction$1.doInvoke(AFunction.java:31)
	at clojure.lang.RestFn.invoke(RestFn.java:408)
	at ring.adapter.jetty9.handlers.sync$_doHandle.invokeStatic(sync.clj:30)
	at ring.adapter.jetty9.handlers.sync$_doHandle.invoke(sync.clj:21)
	at ring.adapter.jetty9.handlers.SyncProxyHandler.doHandle(Unknown Source)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:221)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1381)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:176)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:484)
	at ring.adapter.jetty9.handlers.SyncProxyHandler.doScope(Unknown Source)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:174)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1303)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:129)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
	at org.eclipse.jetty.server.Server.handle(Server.java:563)
	at org.eclipse.jetty.server.HttpChannel$RequestDispatchable.dispatch(HttpChannel.java:1598)
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:753)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:501)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:287)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:314)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)
	at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:421)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:390)

@jdorety
Copy link
Author

jdorety commented Jan 9, 2025

Maybe related to fluree/core#133

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working as expected
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@jdorety