How to debug generic: `Error executing system.db.runPrepQuery` log events

Ignition
,
1

I’m running into Error executing system.db.runPrepQuery log events that I can reliably reproduce with a test setup but I can’t figure out how to dig into the underlying cause of the java.lang.Exception. I know it is related to read/write db transactions occurring on the same table row across two separate perspective threads (with each thread having its own database transaction using isolation level of serializable) - but I don’t fully understand why the db read call is failing.

Is there a way to get more details / logs for when system.db methods fail?

2

the error:

image
image1190×279 71.7 KB

Logger	Time	Message
script	28Aug2025 13:14:20	Error running action 'component.onActionPerformed' on View@C/root/Button_1: Traceback (most recent call last): File "<function:runAction>", line 2, in runAction File "<module:fls_skeleton.service.recipe>", line 726, in test2 File "<module:fls_skeleton.service.recipe>", line 462, in __exit__ File "<module:fls_skeleton.service.recipe>", line 1597, in _get_recipe_json File "<module:fls_skeleton.service.recipe>", line 759, in _get_recipe File "<module:skeleton_base.dao.base_dao>", line 257, in _get_inner File "<module:skeleton_base.dao.base_dao>", line 309, in _filter_inner File "<module:skeleton_base.dao.base_dao>", line 297, in _filter_dataset File "<module:skeleton_base.database.query>", line 681, in run at com.inductiveautomation.ignition.common.script.builtin.AbstractDBUtilities.error(AbstractDBUtilities.java:392) at com.inductiveautomation.ignition.common.script.builtin.AbstractDBUtilities.runPrepQuery(AbstractDBUtilities.java:302) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.base/java.lang.reflect.Method.invoke(Unknown Source) java.lang.Exception: java.lang.Exception: Error executing system.db.runPrepQuery(SELECT "Recipe"."RecipeNo", "Recipe"."Revision", "Recipe"."Created", "Recipe"."Retired", "Recipe"."Type", "Recipe"."User", "Recipe"."LastModified", "Recipe"."Validated", "Recipe"."ValidationDate", "Recipe"."ID" FROM "Recipe" WHERE "RecipeNo" = ? AND "Revision" = ?, Transaction datasource 'sgl_skeletonBase', [A000TEST-1-X29, 0], 6d78e189-bfca-461d-aaf2-4eb4bcff3987)
Transaction Close	28Aug2025 13:14:20	260.130: perspective-worker-85: tx: 6d78e189-bfca-461d-aaf2-4eb4bcff3987, exc: java.lang.Exception: Error executing system.db.runPrepQuery(SELECT "Recipe"."RecipeNo", "Recipe"."Revision", "Recipe"."Created", "Recipe"."Retired", "Recipe"."Type", "Recipe"."User", "Recipe"."LastModified", "Recipe"."Validated", "Recipe"."ValidationDate", "Recipe"."ID" FROM "Recipe" WHERE "RecipeNo" = ? AND "Revision" = ?, Transaction datasource 'sgl_skeletonBase', [A000TEST-1-X29, 0], 6d78e189-bfca-461d-aaf2-4eb4bcff3987)
Select Query	28Aug2025 13:14:20	260.119: perspective-worker-85: ('SELECT "Recipe"."RecipeNo", "Recipe"."Revision", "Recipe"."Created", "Recipe"."Retired", "Recipe"."Type", "Recipe"."User", "Recipe"."LastModified", "Recipe"."Validated", "Recipe"."ValidationDate", "Recipe"."ID" FROM "Recipe" WHERE "RecipeNo" = ? AND "Revision" = ?', ['A000TEST-1-X29', '0'], 'sgl_skeletonBase', u'6d78e189-bfca-461d-aaf2-4eb4bcff3987')
Update Query	28Aug2025 13:14:20	260.108: perspective-worker-85: ('UPDATE "Recipe" SET "Created" = to_timestamp(?, ?), "LastModified" = to_timestamp(?, ?), "RecipeNo" = ?, "Retired" = ?, "Revision" = ?, "Type" = ?, "User" = ?, "Validated" = ?, "ValidationDate" = ? WHERE "RecipeNo" = ? AND "Revision" = ?', [u'2025-08-25 17:20:47:161', 'YYYY-MM-DD HH24:MI:SS:MS', u'2025-08-25 17:21:46:893', 'YYYY-MM-DD HH24:MI:SS:MS', u'A000TEST-1-X29', None, u'0', 'Filtration', u'me', False, None, u'A000TEST-1-X29', u'0'], 'sgl_skeletonBase', u'6d78e189-bfca-461d-aaf2-4eb4bcff3987')
Transaction Close	28Aug2025 13:14:20	260.107: perspective-worker-67: tx: 69eb1255-a9c3-42e0-b3cf-6c0721077c36, exc: None
Select Query	28Aug2025 13:14:20	260.106: perspective-worker-85: ('SELECT "Recipe"."RecipeNo", "Recipe"."Revision", "Recipe"."Created", "Recipe"."Retired", "Recipe"."Type", "Recipe"."User", "Recipe"."LastModified", "Recipe"."Validated", "Recipe"."ValidationDate", "Recipe"."ID" FROM "Recipe" WHERE "RecipeNo" = ? AND "Revision" = ?', ['A000TEST-1-X29', '0'], 'sgl_skeletonBase', u'6d78e189-bfca-461d-aaf2-4eb4bcff3987')
Transaction Commit	28Aug2025 13:14:20	260.105: perspective-worker-67: tx: 69eb1255-a9c3-42e0-b3cf-6c0721077c36
Select Query	28Aug2025 13:14:20	260.100: perspective-worker-85: ('SELECT "Recipe"."RecipeNo", "Recipe"."Revision", "Recipe"."Created", "Recipe"."Retired", "Recipe"."Type", "Recipe"."User", "Recipe"."LastModified", "Recipe"."Validated", "Recipe"."ValidationDate", "Recipe"."ID" FROM "Recipe" WHERE "RecipeNo" = ? AND "Revision" = ?', ['A000TEST-1-X29', '0'], 'sgl_skeletonBase', u'6d78e189-bfca-461d-aaf2-4eb4bcff3987')
Insert Query	28Aug2025 13:14:20	260.094: perspective-worker-67: ('INSERT INTO "AuditLog" ("EventTimestamp", "Actor", "ActorHost", "Action", "ActionTarget", "ActionValue", "StatusCode", "OriginatingSystem", "OriginatingContext") VALUES (to_timestamp(?, ?), ?, ?, ?, ?, ?, ?, ?, ?)', [u'2025-08-28 12:14:16:900', 'YYYY-MM-DD HH24:MI:SS:MS', 'me', None, 'Update', "<Recipe('A000TEST-1-X29', '0')>", u'{"value changed":{"Recipe[\'type\']":{"new value":"filtration","old value":"extrusion"}}}', 0, 'sys:SGL-RTG1:/project:sgls_uirecipemanagement', 1], 'sgl_skeletonBase', u'69eb1255-a9c3-42e0-b3cf-6c0721077c36')
Select Query	28Aug2025 13:14:19	259.925: perspective-worker-67: ('SELECT "Recipe"."RecipeNo", "Recipe"."Revision", "Recipe"."Created", "Recipe"."Retired", "Recipe"."Type", "Recipe"."User", "Recipe"."LastModified", "Recipe"."Validated", "Recipe"."ValidationDate", "Recipe"."ID" FROM "Recipe" WHERE "RecipeNo" = ? AND "Revision" = ?', ['A000TEST-1-X29', '0'], 'sgl_skeletonBase', u'69eb1255-a9c3-42e0-b3cf-6c0721077c36')
Update Query	28Aug2025 13:14:16	256.916: perspective-worker-67: ('UPDATE "Recipe" SET "Created" = to_timestamp(?, ?), "LastModified" = to_timestamp(?, ?), "RecipeNo" = ?, "Retired" = ?, "Revision" = ?, "Type" = ?, "User" = ?, "Validated" = ?, "ValidationDate" = ? WHERE "RecipeNo" = ? AND "Revision" = ?', [u'2025-08-25 17:20:47:161', 'YYYY-MM-DD HH24:MI:SS:MS', u'2025-08-25 17:21:46:893', 'YYYY-MM-DD HH24:MI:SS:MS', u'A000TEST-1-X29', None, u'0', 'Filtration', u'me', False, None, u'A000TEST-1-X29', u'0'], 'sgl_skeletonBase', u'69eb1255-a9c3-42e0-b3cf-6c0721077c36')
Select Query	28Aug2025 13:14:16	256.913: perspective-worker-67: ('SELECT "Recipe"."RecipeNo", "Recipe"."Revision", "Recipe"."Created", "Recipe"."Retired", "Recipe"."Type", "Recipe"."User", "Recipe"."LastModified", "Recipe"."Validated", "Recipe"."ValidationDate", "Recipe"."ID" FROM "Recipe" WHERE "RecipeNo" = ? AND "Revision" = ?', ['A000TEST-1-X29', '0'], 'sgl_skeletonBase', u'69eb1255-a9c3-42e0-b3cf-6c0721077c36')
Select Query	28Aug2025 13:14:16	256.905: perspective-worker-67: ('SELECT "Recipe"."RecipeNo", "Recipe"."Revision", "Recipe"."Created", "Recipe"."Retired", "Recipe"."Type", "Recipe"."User", "Recipe"."LastModified", "Recipe"."Validated", "Recipe"."ValidationDate", "Recipe"."ID" FROM "Recipe" WHERE "RecipeNo" = ? AND "Revision" = ?', ['A000TEST-1-X29', '0'], 'sgl_skeletonBase', u'69eb1255-a9c3-42e0-b3cf-6c0721077c36')
Transaction Begin	28Aug2025 13:14:16	256.900: perspective-worker-85: tx: 6d78e189-bfca-461d-aaf2-4eb4bcff3987
Transaction Begin	28Aug2025 13:14:16	256.897: perspective-worker-67: tx: 69eb1255-a9c3-42e0-b3cf-6c0721077c36
3

My debugging logs leading up to the failure

Logger Time Message
script 28Aug2025 13:14:20 Error running action 'component.onActionPerformed' on View@C/root/Button_1: Traceback (most recent call last): File "function:runAction", line 2, in runAction File "module:fls_skeleton.service.recipe", line 726, in test2 File "module:fls_skeleton.service.recipe", line 462, in _exit_ File "module:fls_skeleton.service.recipe", line 1597, in _get_recipe_json File "module:fls_skeleton.service.recipe", line 759, in _get_recipe File "module:skeleton_base.dao.base_dao", line 257, in _get_inner File "module:skeleton_base.dao.base_dao", line 309, in _filter_inner File "module:skeleton_base.dao.base_dao", line 297, in _filter_dataset File "module:skeleton_base.database.query", line 681, in run at com.inductiveautomation.ignition.common.script.builtin.AbstractDBUtilities.error(AbstractDBUtilities.java:392) at com.inductiveautomation.ignition.common.script.builtin.AbstractDBUtilities.runPrepQuery(AbstractDBUtilities.java:302) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.base/java.lang.reflect.Method.invoke(Unknown Source) java.lang.Exception: java.lang.Exception: Error executing system.db.runPrepQuery(SELECT "Recipe"."RecipeNo", "Recipe"."Revision", "Recipe"."Created", "Recipe"."Retired", "Recipe"."Type", "Recipe"."User", "Recipe"."LastModified", "Recipe"."Validated", "Recipe"."ValidationDate", "Recipe"."ID" FROM "Recipe" WHERE "RecipeNo" = ? AND "Revision" = ?, Transaction datasource 'sgl_skeletonBase', [A000TEST-1-X29, 0], 6d78e189-bfca-461d-aaf2-4eb4bcff3987)
Transaction Close 28Aug2025 13:14:20 260.130: perspective-worker-85: tx: 6d78e189-bfca-461d-aaf2-4eb4bcff3987, exc: java.lang.Exception: Error executing system.db.runPrepQuery(SELECT "Recipe"."RecipeNo", "Recipe"."Revision", "Recipe"."Created", "Recipe"."Retired", "Recipe"."Type", "Recipe"."User", "Recipe"."LastModified", "Recipe"."Validated", "Recipe"."ValidationDate", "Recipe"."ID" FROM "Recipe" WHERE "RecipeNo" = ? AND "Revision" = ?, Transaction datasource 'sgl_skeletonBase', [A000TEST-1-X29, 0], 6d78e189-bfca-461d-aaf2-4eb4bcff3987)
Select Query 28Aug2025 13:14:20 260.119: perspective-worker-85: ('SELECT "Recipe"."RecipeNo", "Recipe"."Revision", "Recipe"."Created", "Recipe"."Retired", "Recipe"."Type", "Recipe"."User", "Recipe"."LastModified", "Recipe"."Validated", "Recipe"."ValidationDate", "Recipe"."ID" FROM "Recipe" WHERE "RecipeNo" = ? AND "Revision" = ?', ['A000TEST-1-X29', '0'], 'sgl_skeletonBase', u'6d78e189-bfca-461d-aaf2-4eb4bcff3987')
Update Query 28Aug2025 13:14:20 260.108: perspective-worker-85: ('UPDATE "Recipe" SET "Created" = to_timestamp(?, ?), "LastModified" = to_timestamp(?, ?), "RecipeNo" = ?, "Retired" = ?, "Revision" = ?, "Type" = ?, "User" = ?, "Validated" = ?, "ValidationDate" = ? WHERE "RecipeNo" = ? AND "Revision" = ?', [u'2025-08-25 17:20:47:161', 'YYYY-MM-DD HH24:MI:SS:MS', u'2025-08-25 17:21:46:893', 'YYYY-MM-DD HH24:MI:SS:MS', u'A000TEST-1-X29', None, u'0', 'Filtration', u'me', False, None, u'A000TEST-1-X29', u'0'], 'sgl_skeletonBase', u'6d78e189-bfca-461d-aaf2-4eb4bcff3987')
Transaction Close 28Aug2025 13:14:20 260.107: perspective-worker-67: tx: 69eb1255-a9c3-42e0-b3cf-6c0721077c36, exc: None
Select Query 28Aug2025 13:14:20 260.106: perspective-worker-85: ('SELECT "Recipe"."RecipeNo", "Recipe"."Revision", "Recipe"."Created", "Recipe"."Retired", "Recipe"."Type", "Recipe"."User", "Recipe"."LastModified", "Recipe"."Validated", "Recipe"."ValidationDate", "Recipe"."ID" FROM "Recipe" WHERE "RecipeNo" = ? AND "Revision" = ?', ['A000TEST-1-X29', '0'], 'sgl_skeletonBase', u'6d78e189-bfca-461d-aaf2-4eb4bcff3987')
Transaction Commit 28Aug2025 13:14:20 260.105: perspective-worker-67: tx: 69eb1255-a9c3-42e0-b3cf-6c0721077c36
Select Query 28Aug2025 13:14:20 260.100: perspective-worker-85: ('SELECT "Recipe"."RecipeNo", "Recipe"."Revision", "Recipe"."Created", "Recipe"."Retired", "Recipe"."Type", "Recipe"."User", "Recipe"."LastModified", "Recipe"."Validated", "Recipe"."ValidationDate", "Recipe"."ID" FROM "Recipe" WHERE "RecipeNo" = ? AND "Revision" = ?', ['A000TEST-1-X29', '0'], 'sgl_skeletonBase', u'6d78e189-bfca-461d-aaf2-4eb4bcff3987')
Insert Query 28Aug2025 13:14:20 260.094: perspective-worker-67: ('INSERT INTO "AuditLog" ("EventTimestamp", "Actor", "ActorHost", "Action", "ActionTarget", "ActionValue", "StatusCode", "OriginatingSystem", "OriginatingContext") VALUES (to_timestamp(?, ?), ?, ?, ?, ?, ?, ?, ?, ?)', [u'2025-08-28 12:14:16:900', 'YYYY-MM-DD HH24:MI:SS:MS', 'me', None, 'Update', "<Recipe('A000TEST-1-X29', '0')>", u'{"value changed":{"Recipe[\'type\']":{"new value":"filtration","old value":"extrusion"}}}', 0, 'sys:SGL-RTG1:/project:sgls_uirecipemanagement', 1], 'sgl_skeletonBase', u'69eb1255-a9c3-42e0-b3cf-6c0721077c36')
Select Query 28Aug2025 13:14:19 259.925: perspective-worker-67: ('SELECT "Recipe"."RecipeNo", "Recipe"."Revision", "Recipe"."Created", "Recipe"."Retired", "Recipe"."Type", "Recipe"."User", "Recipe"."LastModified", "Recipe"."Validated", "Recipe"."ValidationDate", "Recipe"."ID" FROM "Recipe" WHERE "RecipeNo" = ? AND "Revision" = ?', ['A000TEST-1-X29', '0'], 'sgl_skeletonBase', u'69eb1255-a9c3-42e0-b3cf-6c0721077c36')
Update Query 28Aug2025 13:14:16 256.916: perspective-worker-67: ('UPDATE "Recipe" SET "Created" = to_timestamp(?, ?), "LastModified" = to_timestamp(?, ?), "RecipeNo" = ?, "Retired" = ?, "Revision" = ?, "Type" = ?, "User" = ?, "Validated" = ?, "ValidationDate" = ? WHERE "RecipeNo" = ? AND "Revision" = ?', [u'2025-08-25 17:20:47:161', 'YYYY-MM-DD HH24:MI:SS:MS', u'2025-08-25 17:21:46:893', 'YYYY-MM-DD HH24:MI:SS:MS', u'A000TEST-1-X29', None, u'0', 'Filtration', u'me', False, None, u'A000TEST-1-X29', u'0'], 'sgl_skeletonBase', u'69eb1255-a9c3-42e0-b3cf-6c0721077c36')
Select Query 28Aug2025 13:14:16 256.913: perspective-worker-67: ('SELECT "Recipe"."RecipeNo", "Recipe"."Revision", "Recipe"."Created", "Recipe"."Retired", "Recipe"."Type", "Recipe"."User", "Recipe"."LastModified", "Recipe"."Validated", "Recipe"."ValidationDate", "Recipe"."ID" FROM "Recipe" WHERE "RecipeNo" = ? AND "Revision" = ?', ['A000TEST-1-X29', '0'], 'sgl_skeletonBase', u'69eb1255-a9c3-42e0-b3cf-6c0721077c36')
Select Query 28Aug2025 13:14:16 256.905: perspective-worker-67: ('SELECT "Recipe"."RecipeNo", "Recipe"."Revision", "Recipe"."Created", "Recipe"."Retired", "Recipe"."Type", "Recipe"."User", "Recipe"."LastModified", "Recipe"."Validated", "Recipe"."ValidationDate", "Recipe"."ID" FROM "Recipe" WHERE "RecipeNo" = ? AND "Revision" = ?', ['A000TEST-1-X29', '0'], 'sgl_skeletonBase', u'69eb1255-a9c3-42e0-b3cf-6c0721077c36')
Transaction Begin 28Aug2025 13:14:16 256.900: perspective-worker-85: tx: 6d78e189-bfca-461d-aaf2-4eb4bcff3987
Transaction Begin 28Aug2025 13:14:16 256.897: perspective-worker-67: tx: 69eb1255-a9c3-42e0-b3cf-6c0721077c36
4

Please post the full stack trace as pre-formatted text, its easier to read/parse than trying to decipher a screenshot(especially when a screenshot cuts out part of the stack trace).

Please also post a copy of the code that is calling system.db.runPrepQuery, again as preformatted text.

Please see Wiki - how to post code on this forum.

You can edit your post by clicking the pencil icon in the bottom right.

4 Likes
5

Thanks Ryan

I couldn’t find on the Wiki the best way to gather and post logs in the forum… is there a preferred method to pull the logs and paste here? Normally I end up downloading and inspecting the log tables in a db viewer but not sure how to post a full stack trace?

6

Our codebase is highly layered so would be difficult to paste all the methods that are involved in the database call but the final method is:

    @staticmethod
    def time():
        # return a shortened fractional seconds time for debugging
        date = Date().getTime() / 1000.0
        hundreds = int(date) % 1000
        fraction = date % 1
        result = hundreds + fraction
        formatted = "{:.3f}".format(result)
        return formatted

    def run(self, database=None, tx=None, syntax=None):
        query, params = self.describe(syntax)
        system.util.getLogger("Select Query").info("{}: {}: {}".format(Query.time(), Thread.currentThread().getName(), (query, params, database, tx)))                    
        return system.db.runPrepQuery(query, params, database, tx)
7

You could use the “cause” attribute of the error to possibly give more detail like this:

@staticmethod
    def time():
        # return a shortened fractional seconds time for debugging
        date = Date().getTime() / 1000.0
        hundreds = int(date) % 1000
        fraction = date % 1
        result = hundreds + fraction
        formatted = "{:.3f}".format(result)
        return formatted

    def run(self, database=None, tx=None, syntax=None):
        import sys	
        import traceback	
        from java.lang import Throwable

        try:
            query, params = self.describe(syntax)
            system.util.getLogger("Select Query").info("{}: {}: {}".format(Query.time(), Thread.currentThread().getName(), (query, params, database, tx)))                    
            ds = system.db.runPrepQuery(query, params, database, tx)
            return ds
        
        # Exception Handler
        except Exception, e:
            exType, ex, tb = sys.exc_info()
            message = "ERROR on line %d: %s, %s, %s" % (traceback.tb_lineno(tb), exType, ex, e)
            #print or log the message here (message)
            print (message)
            if hasattr(e, 'cause'):
                #print or log the cause here (e.cause)
                print (e.cause)
                
        except Throwable, t:
            exType, ex, tb = sys.exc_info()
            message = "ERROR on line %d: %s, %s, %s" % (traceback.tb_lineno(tb), exType, ex, t)
            #print or log the message here (message)
            print (message)
            if hasattr(t, 'cause'):
                #print or log the cause here (t.cause)
                print (t.cause)
8

Thanks for the suggestion - unfortunately no new information was received in the logs… I did follow on from your idea and logged each line of the stack trace as separate log entries:

    def run(self, database=None, tx=None, syntax=None):
        import sys
        import traceback
        from java.lang import Throwable, Thread

        logger = system.util.getLogger("Select Query")

        def log_line(msg):
            """
            Helper to prepend timestamp and thread name to each log line.
            """
            logger.error(
                "{} [{}] {}".format(Query.time(), Thread.currentThread().getName(), msg)
            )

        try:
            query, params = self.describe(syntax)
            logger.info(
                "{} [{}] {}".format(
                    Query.time(),
                    Thread.currentThread().getName(),
                    (query, params, database, tx),
                )
            )
            return system.db.runPrepQuery(query, params, database, tx)

        except (Exception, Throwable) as err:
            ex_type, ex, tb = sys.exc_info()

            # Log header
            log_line("Exception caught: %s: %s" % (ex_type, ex))

            # Log Python traceback (one line per entry)
            for line in traceback.format_exception(ex_type, ex, tb):
                for subline in line.rstrip().split("\n"):
                    log_line(subline)

            # Log Java cause stack trace if present
            cause = getattr(err, "cause", None)
            if cause:
                log_line("Java cause: %s" % cause)
                try:
                    for ste in cause.getStackTrace():
                        log_line("    at %s" % ste)
                except:
                    # Fallback if it's not a real Java exception
                    log_line(repr(cause))
9

which got me the current transaction is aborted detail:

Select Query	28Aug2025 18:17:51	471.062 [perspective-worker-1033] at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2365)
Select Query	28Aug2025 18:17:51	471.062 [perspective-worker-1033] at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2675)
Select Query	28Aug2025 18:17:51	471.061 [perspective-worker-1033] Java cause: org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block
Select Query	28Aug2025 18:17:51	471.061 [perspective-worker-1033] Exception: java.lang.Exception: Error executing system.db.runPrepQuery(SELECT "Recipe"."RecipeNo", "Recipe"."Revision", "Recipe"."Created", "Recipe"."Retired", "Recipe"."Type", "Recipe"."User", "Recipe"."LastModified", "Recipe"."Validated", "Recipe"."ValidationDate", "Recipe"."ID" FROM "Recipe" WHERE "RecipeNo" = ? AND "Revision" = ?, Transaction datasource 'sgl_skeletonBase', [A000TEST-1-X29, 0], 5faf0e5d-8d73-487e-9510-231a032b93df)
Select Query	28Aug2025 18:17:51	471.061 [perspective-worker-1033] File "<module:skeleton_base.database.query>", line 703, in run
Select Query	28Aug2025 18:17:51	471.061 [perspective-worker-1033] Traceback (most recent call last):
Select Query	28Aug2025 18:17:51	471.059 [perspective-worker-1033] Exception caught: <type 'java.lang.Exception'>: java.lang.Exception: Error executing system.db.runPrepQuery(SELECT "Recipe"."RecipeNo", "Recipe"."Revision", "Recipe"."Created", "Recipe"."Retired", "Recipe"."Type", "Recipe"."User", "Recipe"."LastModified", "Recipe"."Validated", "Recipe"."ValidationDate", "Recipe"."ID" FROM "Recipe" WHERE "RecipeNo" = ? AND "Revision" = ?, Transaction datasource 'sgl_skeletonBase', [A000TEST-1-X29, 0], 5faf0e5d-8d73-487e-9510-231a032b93df)
10

Well, that's your problem. Postgres is throwing an exception because the transaction isn't live. That's either an explicitly created DB transaction you're passing into the system function, an implicitly created one due to your DB connection properties, or an even higher layer one created by Postgres' local configuration.

Don't do that.
Ignition's logging system is rich - collapsing errors to one line each is making your future life harder for no benefit.

Reaching to @pturmel's later.py for the PythonAsJavaException utility class, you can rewrite your snippet for the same end result with less code:

from java.lang import Throwable

def run(self, database=None, tx=None, syntax=None):
	logger = system.util.getLogger("Select Query")

	time = Query.time()
	try:
		logger.mdcPut("queryTime", time)
		query, params = self.describe(syntax)
		logger.infof(
			"%s (%s) db=%s, tx=%s"
			query, params, database, tx
		)
		return system.db.runPrepQuery(query, params, database, tx)
	except Exception as pythonErr:
		logger.error("Python exception encountered", PythonAsJavaException(pythonErr))
	except Throwable as javaErr:
		logger.error("Java exception encountered", javaErr)
	finally:
		logger.mdcRemove("queryTime")

I'd recommend you use Kindling to view Ignition log files. It's a prebuilt desktop application that fully understands our log file format to give you rich presentation.

1 Like
11

Thanks for the feedback Paul. I’ve been meaning to download Kindling for a while now - I will definitely need to set aside some time to do that and learn how to use it. Still not sure what is the best format for sharing logs here in the forum though..

The logging setup I posted above was only meant as a quick and dirty method to try figure out this one particular issue - I definetely don’t plan on leaving it like that!

We are creating the transactions via the system.db.* methods, using a context manager to ensure that the transaction is always closed in the event of an exception. The weird thing is that something in the stack is aborting the transaction (I’m guessing its either postgres or the driver on the detection of me doing something it can’t serialize) but I’m not getting an exception when that happens - its only on the next query using the same tx that I get the exception

Here is a simplified timeline of the process where I can repeatedly get this exception:

[thread 1] tx "a" started
[thread 2] tx "b" started
[thread 1] select query on table "recipe" with tx "a"
[thread 1] select query on table "recipe" with tx "a"
[thread 1] update query on table "recipe" with tx "a"
[thread 1] select query on table "recipe" with tx "a"
[thread 1] insert query on table "audit" with tx "a"
[thread 2] select query on table "recipe" with tx "b"
[thread 1] tx "a" committed
[thread 2] select query on table "recipe" with tx "b"
[thread 1] tx "a" closed
[thread 2] update query on table "recipe" with tx "b" (guessing that tx is being aborted here)
[thread 2] select query on table "recipe" with tx "b" (exception is raised here)
12

Copy paste the entire stack trace, or pertenent log entries, into a preformatted text block.