Server stops accepting connections

rnavarropiris · September 11, 2017, 5:11pm

After running our application for a while, the server stops accepting connections (com.complexible.stardog.server.StardogConnectionException: Connection refused).
Not even the stardog-admin command line tool reacts (so we can no longer e.g. check for declared open connections).

We are still trying to build a minimal script which reproduces this, but still unsuccessfully.

The problem occurs with Stardog 5.0.3 (already occurred in 5.0.2, possibly previous versions also) using the java API also in version 5.0.3. We suspect a connection leak using VersioningConnections.

We use a ConnectionPool:

ConnectionPool pool = ConnectionPoolConfig
        .using(config)
        .minPool(0)
        .maxIdle(maxIdleConnections)
        .maxPool(maxConnections)
        .blockAtCapacity(10000, TimeUnit.MILLISECONDS)
        .expiration(60000, TimeUnit.MILLISECONDS)
        .create();

…from which connections are retrieved:

VersioningConnection conn = pool.obtain().as(VersioningConnection.class);

and after usage, returned to the pool:

pool.release(conn)

We ensure that this last step is executed by wrapping the connection with an own Connection (which extends DelegatingConnection), which executes the release on close. This wrappers are initialized in try-with-resources.

Is there any open/known connection issue with Stardog 5.0.3? Any hints?

Thanks in advance!

rnavarropiris · September 12, 2017, 1:09pm

FYI: using this logging configuration:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
  <Appenders>
    <Console name="stdout" target="SYSTEM_OUT">
      <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
    </Console>
  </Appenders>
  <Loggers>
    <Root level="warn">
      <AppenderRef ref="stdout"/>
    </Root>
    <Logger name="com.complexible.stardog" level="trace" />
    <Logger name="com.complexible.stardog.metadata.MetaProperties" level="info" />
  </Loggers>
</Configuration>

The last information logged by the server is the following:

12:52:08.423 [Stardog.Executor-276] DEBUG com.complexible.stardog.index.disk.btree.impl.BPlusTreeImpl - Tree updated: 1 final: 5,446 pages: 5 (5 init) (1 updated) (4 skipped) (0 split) page/entry: 1,089 time: 00:00:00.439 speed: 0.0K tps
12:52:08.424 [XNIO-1 task-8] DEBUG com.complexible.stardog.index.IndexWriterImpl - Prepared index data in 00:00:00.440
12:52:08.503 [XNIO-1 task-10] DEBUG com.complexible.stardog.StardogKernel - Retrieving database 'stardog' from system.
12:52:08.503 [XNIO-1 task-10] DEBUG com.complexible.stardog.StardogKernel - 'stardog' already loaded
12:52:08.507 [XNIO-1 task-10] DEBUG com.complexible.stardog.db.DatabaseImpl - Opening connection to stardog
12:52:08.564 [XNIO-1 task-10] DEBUG com.complexible.stardog.db.DatabaseImpl - Connection successfully opened in 57
12:52:08.560 [XNIO-1 task-8] DEBUG com.complexible.stardog.dht.impl.AbstractHashPage - Put Page: 180 Entry: [7A8DE68616DCF3EB7EA6EAAA8182B6B6DAEA8402->2768501]
12:52:08.566 [XNIO-1 task-8] TRACE com.complexible.stardog.dht.dictionary.HashDictionary - Index: 2768501 Value: tag:stardog:api:versioning:version:29759cb2-5cd6-44ce-9cbd-4ad756c92dca Bytes (47): 0700000000000001E1002432393735396362322D356364362D343463652D396362642D346164373536633932646361
12:52:08.568 [XNIO-1 task-8] DEBUG com.complexible.stardog.dht.impl.AbstractHashPage - Put Page: 238 Entry: [DE8FE0ADE887A8F4B2D91989842226BE2CBF9B50->2768548]
12:52:08.569 [XNIO-1 task-8] TRACE com.complexible.stardog.dht.dictionary.HashDictionary - Index: 2768548 Value: "https://ns.eccenca.com/elds"6372832e-2d45-4970-9f3b-5670494a41da"^^<http://www.w3.org/2001/XMLSchema#string> Bytes (70): 060000004068747470733A2F2F6E732E656363656E63612E636F6D2F656C64732236333732383332652D326434352D343937302D396633622D35363730343934613431646109
12:52:08.715 [XNIO-1 task-14] DEBUG com.complexible.stardog.db.DatabaseImpl - Closing wrapper connection to stardog
12:52:08.720 [XNIO-1 task-14] DEBUG com.complexible.stardog.db.DatabaseConnectionImpl - Closing a connection to stardog
12:52:08.720 [XNIO-1 task-14] DEBUG com.complexible.stardog.index.IndexConnectionImpl - Closing connection: Connection(stardog; 1 readers, no writers)
12:52:08.719 [XNIO-1 task-8] DEBUG com.complexible.stardog.index.IndexConnectionImpl - Closing connection: Connection(versioning; 0 readers, no writers)
12:52:08.741 [Stardog.Executor-276] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:08.743 [XNIO-1 task-10] TRACE com.complexible.stardog.plan.eval.ExecutionContext - Created solution factory: LeanSolutionFactory
12:52:08.746 [Stardog.Executor-266] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:08.780 [XNIO-1 task-10] DEBUG com.complexible.stardog.plan.eval.ExecutionContext - Operator tree:
Projection([0, 1, 3, 5, 6])
  Bind(0 AS tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3,1 AS tag:stardog:api:versioning:Version)
    LoopJoin(outer=true)
      LoopJoin
        LoopJoin
          MergeJoin(key=4)
            IndexScan(order=SPOC, first=tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3, second=http://www.w3.org/ns/prov#wasAttributedTo, third=Var(4), context=Var(2))
            IndexScan(order=PSOC, first=Var(4), second=http://www.w3.org/2000/01/rdf-schema#label, third=Var(3), context=Var(2))
          IndexScan(order=SPO, first=tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3, second=http://www.w3.org/1999/02/22-rdf-syntax-ns#type, third=tag:stardog:api:versioning:Version)
        IndexScan(order=SPO, first=tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3, second=http://www.w3.org/ns/prov#generatedAtTime, third=Var(5))
      IndexScan(order=SPO, first=tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3, second=http://www.w3.org/2000/01/rdf-schema#comment, third=Var(6))

12:52:08.780 [XNIO-1 task-10] DEBUG com.complexible.stardog.plan.eval.ExecutionContext - Operator tree:
Projection([0, 1, 3, 5, 6])
  Bind(0 AS tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3,1 AS tag:stardog:api:versioning:Version)
    LoopJoin(outer=true)
      LoopJoin
        LoopJoin
          MergeJoin(key=4)
            IndexScan(order=SPOC, first=tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3, second=http://www.w3.org/ns/prov#wasAttributedTo, third=Var(4), context=Var(2))
            IndexScan(order=PSOC, first=Var(4), second=http://www.w3.org/2000/01/rdf-schema#label, third=Var(3), context=Var(2))
          IndexScan(order=SPO, first=tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3, second=http://www.w3.org/1999/02/22-rdf-syntax-ns#type, third=tag:stardog:api:versioning:Version)
        IndexScan(order=SPO, first=tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3, second=http://www.w3.org/ns/prov#generatedAtTime, third=Var(5))
      IndexScan(order=SPO, first=tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3, second=http://www.w3.org/2000/01/rdf-schema#comment, third=Var(6))

12:52:08.781 [XNIO-1 task-10] DEBUG com.complexible.stardog.plan.eval.ExecutablePlanImpl - Executable plan:
Projection([0, 1, 3, 5, 6])
  Bind(0 AS tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3,1 AS tag:stardog:api:versioning:Version)
    LoopJoin(outer=true)
      LoopJoin
        LoopJoin
          MergeJoin(key=4)
            IndexScan(order=SPOC, first=tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3, second=http://www.w3.org/ns/prov#wasAttributedTo, third=Var(4), context=Var(2))
            IndexScan(order=PSOC, first=Var(4), second=http://www.w3.org/2000/01/rdf-schema#label, third=Var(3), context=Var(2))
          IndexScan(order=SPO, first=tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3, second=http://www.w3.org/1999/02/22-rdf-syntax-ns#type, third=tag:stardog:api:versioning:Version)
        IndexScan(order=SPO, first=tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3, second=http://www.w3.org/ns/prov#generatedAtTime, third=Var(5))
      IndexScan(order=SPO, first=tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3, second=http://www.w3.org/2000/01/rdf-schema#comment, third=Var(6))

12:52:08.781 [XNIO-1 task-10] DEBUG com.complexible.stardog.plan.eval.ExecutablePlanImpl - Executable plan:
Projection([0, 1, 3, 5, 6])
  Bind(0 AS tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3,1 AS tag:stardog:api:versioning:Version)
    LoopJoin(outer=true)
      LoopJoin
        LoopJoin
          MergeJoin(key=4)
            IndexScan(order=SPOC, first=tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3, second=http://www.w3.org/ns/prov#wasAttributedTo, third=Var(4), context=Var(2))
            IndexScan(order=PSOC, first=Var(4), second=http://www.w3.org/2000/01/rdf-schema#label, third=Var(3), context=Var(2))
          IndexScan(order=SPO, first=tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3, second=http://www.w3.org/1999/02/22-rdf-syntax-ns#type, third=tag:stardog:api:versioning:Version)
        IndexScan(order=SPO, first=tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3, second=http://www.w3.org/ns/prov#generatedAtTime, third=Var(5))
      IndexScan(order=SPO, first=tag:stardog:api:versioning:version:f70d4d32-ca8a-4d3d-96ba-5cf9d76ebad3, second=http://www.w3.org/2000/01/rdf-schema#comment, third=Var(6))

12:52:08.781 [XNIO-1 task-10] DEBUG com.complexible.stardog.db.DatabaseImpl - Closing wrapper connection to stardog
12:52:08.782 [XNIO-1 task-10] DEBUG com.complexible.stardog.db.DatabaseConnectionImpl - Closing a connection to stardog
12:52:08.782 [XNIO-1 task-10] DEBUG com.complexible.stardog.index.IndexConnectionImpl - Closing connection: Connection(stardog; 1 readers, no writers)
12:52:08.833 [Stardog.Executor-276] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:08.834 [Stardog.Executor-266] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:08.834 [XNIO-1 task-8] DEBUG com.complexible.stardog.index.IndexWriterImpl - Preparing for commit
12:52:08.834 [XNIO-1 task-8] DEBUG com.complexible.stardog.index.AbstractIndexData - Dispose DiskIndexData(326718625)
12:52:08.834 [Stardog.Executor-266] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:08.852 [Stardog.Executor-276] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:08.872 [Stardog.Executor-277] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:08.876 [Stardog.Executor-278] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:08.887 [Stardog.Executor-232] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:08.922 [Stardog.Executor-232] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:08.887 [Stardog.Executor-271] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:08.923 [Stardog.Executor-271] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:08.886 [Stardog.Executor-263] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:08.876 [Stardog.Executor-278] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:08.886 [Stardog.Executor-242] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:08.924 [Stardog.Executor-242] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:08.886 [Stardog.Executor-263] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:08.924 [Stardog.Executor-263] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:08.932 [Stardog.Executor-266] DEBUG com.complexible.stardog.index.disk.btree.impl.BPlusTreeImpl - Tree updated: 2 final: 15,244 pages: 10 (10 init) (2 updated) (8 skipped) (0 split) page/entry: 1,524 time: 00:00:00.098 speed: 0.0K tps
12:52:08.932 [Stardog.Executor-266] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:08.932 [Stardog.Executor-232] DEBUG com.complexible.stardog.index.disk.btree.impl.BPlusTreeImpl - Tree updated: 14 final: 127,260 pages: 1,083 (1,083 init) (3 updated) (1,080 skipped) (0 split) page/entry: 117 time: 00:00:00.045 speed: 0.3K tps
12:52:08.943 [Stardog.Executor-266] DEBUG com.complexible.stardog.index.disk.btree.impl.BPlusTreeImpl - Tree updated: 4 final: 36,999 pages: 751 (751 init) (2 updated) (749 skipped) (0 split) page/entry: 49 time: 00:00:00.109 speed: 0.0K tps
12:52:08.945 [Stardog.Executor-242] DEBUG com.complexible.stardog.index.disk.btree.impl.BPlusTreeImpl - Tree updated: 14 final: 127,260 pages: 2,228 (2,228 init) (6 updated) (2,222 skipped) (0 split) page/entry: 57 time: 00:00:00.058 speed: 0.2K tps
12:52:08.945 [Stardog.Executor-266] DEBUG com.complexible.stardog.index.disk.btree.impl.BPlusTreeImpl - Tree updated: 14 final: 127,260 pages: 142 (142 init) (3 updated) (139 skipped) (0 split) page/entry: 896 time: 00:00:00.111 speed: 0.1K tps
12:52:09.188 [Stardog.Executor-277] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:09.321 [Stardog.Executor-276] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:10.096 [Stardog.Executor-276] DEBUG com.complexible.stardog.index.disk.btree.impl.BPlusTreeImpl - Tree updated: 9 final: 23,678 pages: 949 (949 init) (3 updated) (573 skipped) (0 split) page/entry: 24 time: 00:00:01.244 speed: 0.0K tps
12:52:10.121 [Stardog.Executor-263] DEBUG com.complexible.stardog.index.disk.btree.impl.BPlusTreeImpl - Tree updated: 14 final: 127,260 pages: 836 (836 init) (10 updated) (807 skipped) (0 split) page/entry: 152 time: 00:00:01.234 speed: 0.0K tps
12:52:10.096 [Stardog.Executor-276] DEBUG com.complexible.stardog.index.disk.btree.impl.BPlusTreeImpl - Tree updated: 9 final: 23,678 pages: 949 (949 init) (3 updated) (573 skipped) (0 split) page/entry: 24 time: 00:00:01.244 speed: 0.0K tps
12:52:11.962 [Stardog.Executor-278] DEBUG com.complexible.stardog.index.disk.btree.impl.DiskExternalSorter - 0 buckets created
12:52:11.888 [Stardog.Executor-271] DEBUG com.complexible.stardog.index.disk.btree.impl.BPlusTreeImpl - Tree updated: 14 final: 127,260 pages: 2,657 (2,657 init) (11 updated) (2,614 skipped) (0 split) page/entry: 47 time: 00:00:02.995 speed: 0.0K tps
12:52:12.897 [Stardog.Executor-278] DEBUG com.complexible.stardog.index.disk.btree.impl.BPlusTreeImpl - Tree updated: 10 final: 73,980 pages: 51 (51 init) (3 updated) (48 skipped) (0 split) page/entry: 1,450 time: 00:00:04.021 speed: 0.0K tps

I noticed that the log message com.complexible.stardog.index.IndexWriterImpl - Prepared index data in ... does not arrive as in previous steps, maybe the process gets stuck at this point?

stephen · September 12, 2017, 1:42pm

Does stardog-admin server status show an increasing number of open connections as your application runs but before it gets to the point where it stops accepting connections?

rnavarropiris · September 19, 2017, 8:34am

Hi Stephen!

I checked the server status every few seconds using stardog-admin server status and the number of connections did not increase, for the whole execution was kept (increased & decreased) between 0 and 3-4.

It might be a Docker related problem, as Stardog is started as a docker container. The problem seems to occur in this context only.
Do you have any experience with Stardog in docker? Any know issues that could help us identify the problem?

Thanks in advance!

hmottestad · September 19, 2017, 10:21am

We run Stardog in docker. Only issue we’ve had was when docker would kill Stardog which would corrupt the index. But that bug was fixed.

For us a connection issue with Stardog was happening because we didn’t close all our resources that we opened (.getStatements(…)).

Edit. I’m a client.

rnavarropiris · September 20, 2017, 8:05am

@hmottestad

Thanks for the feedback! we already discarded the possibility of open resources, as the information provided by stardog-admin server status shows that the connections and transactions are closed. Furthermore, on a native environment the application does not get to that limit.

@stephen

I think I found something that might explain the current issues.
First I observed that the server was not rejecting connections, but completely gone. The process was apparently killed by the system.

Regarding the STARDOG_JAVA_ARGS environment variable, as stated by the documentation, is used to determine the configuration of the server. However, this configuration is not used exclusively by the server (in other words, when executing stardog-admin server start) but always used by the stardog-admin tool.

This means, that all calls to stardog-admin server status (also used by our docker healthcheck) initialize a JVM with the same configuration as the server, in this case with a big amount of maximum heap space and direct memory.
I suspect, that this could be the reason for the current misbehavior.

In any case, if my suspicions are correct, this behavior should be corrected and (more or less) look like this:

use JAVA_OPTS/JAVA_TOOL_OPTIONS as default java properties for any stardog or stardog-admin execution
use STARDOG_JAVA_ARGS to override the standard JAVA_OPTS/JAVA_TOOL_OPTIONS exclusively on execution of stardog-admin server start

I'm running more tests now making sure that the calls to stardog-admin server status allocate a small amount of memory only, so far no more "sudden deaths" of the server occurred.

hmottestad · September 20, 2017, 8:42am

stardog-admin server status doesn’t show if resources are left open. As far as I know there is no simple way to get Stardog to tell you if you’ve forgot to close a result set from a query. A connection or transaction can be closed and still leave result sets open. This doesn’t mean that this is your problem, but just wanted to make you aware of our experience.

Topic		Replies	Views
"delegating connection" error with Stardog API usage Bug	9	657	February 16, 2022
Connection to Stardog causes java.lang.OutOfMemoryError Bug	2	432	January 10, 2020
How to use connections with Stardog Support	2	437	November 21, 2018
Timeout connectionpool Support	1	276	September 18, 2019
Stardog running out of memory when using connection pool Bug	8	1004	August 25, 2021

Server stops accepting connections

Related topics