Hi, I have something that seems unusual, so lookin...

# exposed

[Andrew]

Hi, I have something that seems unusual, so looking for some help:
Summary is that multiple 'logging' of sql is output, even though there's only a single insert statement. Also, as you can see it's running a COUNT (twice??) even though the line in the code to do the count hasn't been executed yet (I have the breakpoint on the line...)
Thanks!

[Andrew]

Another example of 2 inserts.

SQL: INSERT INTO items_t_ju8 (classification, id, in_place, "name", score) VALUES ('CRITICAL', 'e4d778b6-8a49-4dc4-a089-b130a6c3dbce', FALSE, 'vCh0q', 0.9003645)
SQL: INSERT INTO items_t_ju8 (classification, id, in_place, "name", score) VALUES ('CRITICAL', '675f9e66-4670-4c08-895a-3f29db726166', TRUE, '9D9ZR', 0.59893584)
SQL: INSERT INTO items_t_ju8 (classification, id, in_place, "name", score) VALUES ('CRITICAL', 'e4d778b6-8a49-4dc4-a089-b130a6c3dbce', FALSE, 'vCh0q', 0.9003645)
SQL: INSERT INTO items_t_ju8 (classification, id, in_place, "name", score) VALUES ('CRITICAL', '675f9e66-4670-4c08-895a-3f29db726166', TRUE, '9D9ZR', 0.59893584)
SQL: INSERT INTO items_t_ju8 (classification, id, in_place, "name", score) VALUES ('CRITICAL', 'e4d778b6-8a49-4dc4-a089-b130a6c3dbce', FALSE, 'vCh0q', 0.9003645)
SQL: INSERT INTO items_t_ju8 (classification, id, in_place, "name", score) VALUES ('CRITICAL', '675f9e66-4670-4c08-895a-3f29db726166', TRUE, '9D9ZR', 0.59893584)
SQL: INSERT INTO items_t_ju8 (classification, id, in_place, "name", score) VALUES ('CRITICAL', 'e4d778b6-8a49-4dc4-a089-b130a6c3dbce', FALSE, 'vCh0q', 0.9003645)
SQL: INSERT INTO items_t_ju8 (classification, id, in_place, "name", score) VALUES ('CRITICAL', '675f9e66-4670-4c08-895a-3f29db726166', TRUE, '9D9ZR', 0.59893584)
SQL: INSERT INTO items_t_ju8 (classification, id, in_place, "name", score) VALUES ('CRITICAL', 'e4d778b6-8a49-4dc4-a089-b130a6c3dbce', FALSE, 'vCh0q', 0.9003645)
SQL: INSERT INTO items_t_ju8 (classification, id, in_place, "name", score) VALUES ('CRITICAL', '675f9e66-4670-4c08-895a-3f29db726166', TRUE, '9D9ZR', 0.59893584)
SQL: INSERT INTO items_t_ju8 (classification, id, in_place, "name", score) VALUES ('CRITICAL', 'e4d778b6-8a49-4dc4-a089-b130a6c3dbce', FALSE, 'vCh0q', 0.9003645)
SQL: INSERT INTO items_t_ju8 (classification, id, in_place, "name", score) VALUES ('CRITICAL', '675f9e66-4670-4c08-895a-3f29db726166', TRUE, '9D9ZR', 0.59893584)
SQL: INSERT INTO items_t_ju8 (classification, id, in_place, "name", score) VALUES ('CRITICAL', 'e4d778b6-8a49-4dc4-a089-b130a6c3dbce', FALSE, 'vCh0q', 0.9003645)
SQL: INSERT INTO items_t_ju8 (classification, id, in_place, "name", score) VALUES ('CRITICAL', '675f9e66-4670-4c08-895a-3f29db726166', TRUE, '9D9ZR', 0.59893584)
SQL: INSERT INTO items_t_ju8 (classification, id, in_place, "name", score) VALUES ('CRITICAL', 'e4d778b6-8a49-4dc4-a089-b130a6c3dbce', FALSE, 'vCh0q', 0.9003645)
SQL: INSERT INTO items_t_ju8 (classification, id, in_place, "name", score) VALUES ('CRITICAL', '675f9e66-4670-4c08-895a-3f29db726166', TRUE, '9D9ZR', 0.59893584)
SQL: INSERT INTO items_t_ju8 (classification, id, in_place, "name", score) VALUES ('CRITICAL', 'e4d778b6-8a49-4dc4-a089-b130a6c3dbce', FALSE, 'vCh0q', 0.9003645)
SQL: INSERT INTO items_t_ju8 (classification, id, in_place, "name", score) VALUES ('CRITICAL', '675f9e66-4670-4c08-895a-3f29db726166', TRUE, '9D9ZR', 0.59893584)

[Chantal Loncle]

Hi @Andrew Could you please confirm how your logging is currently setup?

With that many duplicates being output, for both inserts and selects, the only way I could simulate it was by repeatedly adding multiple loggers across multiple transactions, something like:

transaction {
    addLogger(StdOutSqlLogger)
    // query #1 will log once

    transaction {
        addLogger(StdOutSqlLogger)
        // query #2 will log twice
    }
}

// if the queries were instead DAO inserts, each would log twice because
// inserts are implicitly flushed at the end of nested transactions

If you can confirm that you don't have multiple Exposed loggers going at the same time, please then confirm the following so we can look further into this:
• What Exposed version is being used?
• You're performing the count query using DSL. Are you performing inserts also with DSL, or with DAO?
• Have you set keepLoadedReferencesOutOfTransaction = true? This has caused duplicate selects in the past, but only when loading entities using load() or with(). And that bug should have been fixed in version 0.50.0.

[Andrew]

Hi @Chantal Loncle - I'm running these as basic tests, so it's in a single txn with only one logger set.

transaction {
  addLogger(StdOutSqlLogger)
  SchemaUtils.create(store)
}

• I am using 0.55.0
• I have noticed logging only outputs like that when using IntelliJ to run the tests (whether gradle or Intellij). When I run from terminal, no logging issues.
• Have not set that flag anywhere (assume it's not a default)
• Insert is DSL (screenshot). Not using DAO at all.

[Chantal Loncle]

Alright so would dbQuery just be something like this?

fun <T> dbQuery(block: () -> T): T = transaction {
    addLogger(StdOutSqlLogger)
    block()
}

I tried to spin up some tests, but I haven't been able to get any to duplicate the logs with IntelliJ so far.

Could you try some things please:
1. In your test database setup with Database.connect, please use DatabaseConfig { useNestedTransactions = true }. Do the logs still duplicate even with this setting?
◦ This is unlikely to make a difference since the logs don't duplicate when run from the terminal.
2. Do you have something like log4j2 or logback configured somewhere, like in an .xml or properties? Is there any chance of potential additivity being configured in your test resources root?
3. What if you were to copy and paste the code for table creation and the content from create() into a single transaction in a main() for example, instead of in a test function/suite? Do you get the same logs?

More than likely I'll have to request a minimally reproducible sample of how the tests are being run and how logs are set up to see if I can help troubleshoot further.

[Andrew]

I'll do some shuffling to see if I can reproduce in a simple main and come back to you.

[Andrew]

@Chantal Loncle Must be something with my code. I can extract everything out into something simple and it won't print multiples, but as soon as I use the repo structure I have, it prints...
I'll keep screwing around to see what I can find. It's a little interesting I have to say..

[Andrew]

@Chantal Loncle Is there a set of examples of how to dynamically name tables for multitenancy that I could look at?

[Chantal Loncle]

None currently in our sample projects, but have your tried overriding tableName property? Here are some examples I found: example 1, example 2

[Andrew]

Thanks, I have it sorted now.