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

[Suggestion] Log the SQL query when an exception is thrown #288

Closed
AllanWang opened this issue Apr 19, 2018 · 7 comments
Closed

[Suggestion] Log the SQL query when an exception is thrown #288

AllanWang opened this issue Apr 19, 2018 · 7 comments
Assignees
@Tapac
Labels
enhancement

Comments

@AllanWang
Copy link
Contributor

Using logger.addLogger(StdOutSqlLogger), we can see the query outputs whenever one has been executed. However, if any exception is thrown, we just get the message from the sql dependency, and no information (from what I am aware) on the query that is being generated. It would help a lot if there was a way of outputting the erroneous line for debugging purposes
@Tapac
Copy link
Contributor

Tapac commented Apr 24, 2018

Right now every SQLException has thrown inside transaction block logged to exposedLogger, which uses slf4j. Beside an exception also preparedStatement instance add to log message, maybe .toString() on some statements doesn't provide enough information?

Could you provide a sample output without query you get on exception?

@AllanWang
Copy link
Contributor Author

No statement seems to be logged when there is an exception either in the creation of the statement (eg using ignore when it isn't supported) or an exception from the db driver. I get that the former might not be loggable, and the exception thrown should have enough information to fix it, but for exceptions thrown after the statement is created, perhaps it can be logged before the call so it is always visible?

As a simple example, when inserting a row with a missing column, the statement is never logged if it fails:

org.postgresql.util.PSQLException: ERROR: column excluded.ldap_sync_time does not exist
  Position: 546

	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2433)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2178)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:306)
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:441)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:365)
	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:155)
	at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:132)
	at org.jetbrains.exposed.sql.statements.InsertStatement.execInsertFunction(InsertStatement.kt:85)
	at org.jetbrains.exposed.sql.statements.InsertStatement.executeInternal(InsertStatement.kt:94)

There were a few other instances where there were crashes as I was trying to make new Exposed statements though I do not have them at hand.

To go hand in hand with this, is there a way of simply printing the generated statement so we can see if it matches what we want to create?

@Tapac Tapac self-assigned this Apr 26, 2018
@AllanWang
Copy link
Contributor Author

Another example when testing #298:

Exception in thread "main" org.postgresql.util.PSQLException: ERROR: there is no unique or exclusion constraint matching the ON CONFLICT specification

This likely has to do with a replace query, though I will have to figure out what exactly is getting called as it isn't printed

Tapac added a commit that referenced this issue May 8, 2018
@Tapac
#288 [Suggestion] Log the SQL query when an exception is thrown
1e3bcb4
@Tapac
Copy link
Contributor

Tapac commented May 8, 2018

Fixed in master, please check that this is what you expected

Tapac added a commit that referenced this issue May 8, 2018
@Tapac
#288 [Suggestion] Log the SQL query when an exception is thrown / Mis…
8186d51 
…sed import in test
Tapac added a commit that referenced this issue May 8, 2018
@Tapac
#288 [Suggestion] Log the SQL query when an exception is thrown / Tes…
afe38b6 
…t fixed
@AllanWang
Copy link
Contributor Author

I'm not entirely sure if this works or not.

I tried to add unit tests to my project with travis, and I received the following error:

ca.allanwang.mcgill.db.DbTest > batchInsert STANDARD_OUT
    SQL: DROP TABLE  IF EXISTS testusergroups
    SQL: DROP TABLE  IF EXISTS testusers
    SQL: DROP TABLE  IF EXISTS testgroups
    SQL: CREATE TABLE IF NOT EXISTS testgroups (name VARCHAR(20) PRIMARY KEY)
    SQL: CREATE TABLE IF NOT EXISTS testusers (id VARCHAR(20) PRIMARY KEY, name VARCHAR(20) NOT NULL)
    SQL: CREATE TABLE IF NOT EXISTS testusergroups (test_users_id VARCHAR(20), test_groups_name VARCHAR(20), CONSTRAINT pk_TestUserGroups PRIMARY KEY (test_users_id, test_groups_name),  FOREIGN KEY (test_users_id) REFERENCES testusers(id) ON DELETE CASCADE,  FOREIGN KEY (test_groups_name) REFERENCES testgroups(name) ON DELETE CASCADE)
    SQL: DROP TABLE  IF EXISTS testusergroups
    SQL: DROP TABLE  IF EXISTS testusers
    SQL: DROP TABLE  IF EXISTS testgroups
    SQL: CREATE TABLE IF NOT EXISTS testgroups (name VARCHAR(20) PRIMARY KEY)
    SQL: CREATE TABLE IF NOT EXISTS testusers (id VARCHAR(20) PRIMARY KEY, name VARCHAR(20) NOT NULL)
    SQL: CREATE TABLE IF NOT EXISTS testusergroups (test_users_id VARCHAR(20), test_groups_name VARCHAR(20), CONSTRAINT pk_TestUserGroups PRIMARY KEY (test_users_id, test_groups_name),  FOREIGN KEY (test_users_id) REFERENCES testusers(id) ON DELETE CASCADE,  FOREIGN KEY (test_groups_name) REFERENCES testgroups(name) ON DELETE CASCADE)
    SQL: DROP TABLE  IF EXISTS testusergroups
    SQL: DROP TABLE  IF EXISTS testusers
    SQL: DROP TABLE  IF EXISTS testgroups
    SQL: CREATE TABLE IF NOT EXISTS testgroups (name VARCHAR(20) PRIMARY KEY)
    SQL: CREATE TABLE IF NOT EXISTS testusers (id VARCHAR(20) PRIMARY KEY, name VARCHAR(20) NOT NULL)
    SQL: CREATE TABLE IF NOT EXISTS testusergroups (test_users_id VARCHAR(20), test_groups_name VARCHAR(20), CONSTRAINT pk_TestUserGroups PRIMARY KEY (test_users_id, test_groups_name),  FOREIGN KEY (test_users_id) REFERENCES testusers(id) ON DELETE CASCADE,  FOREIGN KEY (test_groups_name) REFERENCES testgroups(name) ON DELETE CASCADE)
ca.allanwang.mcgill.db.DbTest > batchInsert STANDARD_ERROR
    org.postgresql.util.PSQLException: ERROR: syntax error at or near "ON"
      Position: 49
    	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2433)
    	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2178)
    	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:306)
    	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:441)
    	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:365)
    	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:155)
    	at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:132)
    	at org.jetbrains.exposed.sql.statements.InsertStatement.execInsertFunction(InsertStatement.kt:85)
    	at org.jetbrains.exposed.sql.statements.InsertStatement.executeInternal(InsertStatement.kt:94)
    	at org.jetbrains.exposed.sql.statements.InsertStatement.executeInternal(InsertStatement.kt:11)
    	at org.jetbrains.exposed.sql.statements.Statement.executeIn$exposed(Statement.kt:55)
    	at org.jetbrains.exposed.sql.Transaction.exec(Transaction.kt:111)
    	at org.jetbrains.exposed.sql.Transaction.exec(Transaction.kt:105)
    	at org.jetbrains.exposed.sql.statements.Statement.execute(Statement.kt:27)
    	at org.jetbrains.exposed.sql.QueriesKt.replace(Queries.kt:112)
    	at ca.allanwang.mcgill.db.bindings.DataReceiverKt.save(DataReceiver.kt:66)
    	at ca.allanwang.mcgill.db.tables.TestUsersKt.save(TestUsers.kt:56)
    	at ca.allanwang.mcgill.db.DbTest$batchInsert$1.invoke(DbTest.kt:45)
    	at ca.allanwang.mcgill.db.DbTest$batchInsert$1.invoke(DbTest.kt:14)
    	at ca.allanwang.mcgill.db.internal.HelpersKt$testTransaction$1.invoke(Helpers.kt:33)
    	at ca.allanwang.mcgill.db.internal.HelpersKt$testTransaction$1.invoke(Helpers.kt)
    	at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManagerKt.inTopLevelTransaction(ThreadLocalTransactionManager.kt:101)
    	at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManagerKt.transaction(ThreadLocalTransactionManager.kt:72)
    	at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManagerKt.transaction(ThreadLocalTransactionManager.kt:55)
    	at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManagerKt.transaction$default(ThreadLocalTransactionManager.kt:55)
    	at ca.allanwang.mcgill.db.internal.HelpersKt.testTransaction(Helpers.kt:29)
    	at ca.allanwang.mcgill.db.internal.HelpersKt.testTransaction$default(Helpers.kt:28)
    	at ca.allanwang.mcgill.db.DbTest.batchInsert(DbTest.kt:44)
    	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    	at java.lang.reflect.Method.invoke(Method.java:498)
    	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
    	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
    	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
    	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
    	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
    	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
    	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
    	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
    	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
    	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
    	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
    	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
    	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
    	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
    	at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.runTestClass(JUnitTestClassExecutor.java:106)
    	at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:58)
    	at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:38)
    	at org.gradle.api.internal.tasks.testing.junit.AbstractJUnitTestClassProcessor.processTestClass(AbstractJUnitTestClassProcessor.java:66)
    	at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:51)
    	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    	at java.lang.reflect.Method.invoke(Method.java:498)
    	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
    	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
    	at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:32)
    	at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:93)
    	at com.sun.proxy.$Proxy1.processTestClass(Unknown Source)
    	at org.gradle.api.internal.tasks.testing.worker.TestWorker.processTestClass(TestWorker.java:109)
    	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    	at java.lang.reflect.Method.invoke(Method.java:498)
    	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
    	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
    	at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:155)
    	at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:137)
    	at org.gradle.internal.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:404)
    	at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:63)
    	at org.gradle.internal.concurrent.ManagedExecutorImpl$1.run(ManagedExecutorImpl.java:46)
    	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    	at org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:55)
    	at java.lang.Thread.run(Thread.java:748)

I believe it is attempting to do the transaction 3 times, but each time only shows the creation and deletion of tables. I have already tested in another method that that portion is fine.

Another thing to note, but by default, only org.postgresql.util.PSQLException at DbTest.kt:52 is printed when an error occurs. Perhaps the message should be printed as well? The message above was by printing the whole stack trace myself

@Tapac
Copy link
Contributor

Tapac commented May 16, 2018

Fixes for that issue wasn't released yet. Do you mind to test it again if I'll provide you with a custom snapshot jar?

@AllanWang
Copy link
Contributor Author

I can test it. It may be easier to import if you just push to a branch and I build the specific commit with jitpack

Tapac added a commit that referenced this issue Jun 11, 2018
@Tapac
#288 [Suggestion] Log the SQL query when an exception is thrown / tra…
170187c 
…nsaction added to ExposedSQLException
@Tapac Tapac closed this as completed Jun 25, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@Tapac Tapac

Labels
enhancement
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@Tapac @AllanWang