DB logging logs statements twice?

[Jeppe Nejsum Madsen]

Hi,

Just wanted to update to the new db logging by adding the following to
boot:

DB.addLogFunc {
case (query:DBLog, time) => {
LogBoot.loggerByName("query").info(">>> All queries took " + time + "ms: ")
query.statementEntries.foreach({ case DBLogEntry(stmt, duration) => LogBoot.loggerByName("query").info(" "+stmt + " took " + duration + "ms")})
LogBoot.loggerByName("query").info("<<< End queries")
}
}

But it seems all executed statements are logged twice. I have this
snippet:

def currentUser(xhtml: Group): NodeSeq = Text(User.currentUser.dmap(S.?("Anonym"))(user => user.firstName + " " + user.lastName))

This logs:

14:46:09.068 [tp-1029120287-4] INFO query - >>> All queries took 5ms:
14:46:09.068 [tp-1029120287-4] INFO query - Exec query "SELECT users.id, users.firstname, users.lastname, users.email, users.locale, users.timezone, users.password_pw, users.password_slt, users.account_id, users.superuser, users.uniqueid, users.validated FROM users WHERE id = 2 (scale -5)" : org.postgresql.jdbc4.Jdbc4ResultSet@77f31432 took 4ms
14:46:09.069 [tp-1029120287-4] INFO query - <<< End queries
14:46:09.069 [tp-1029120287-4] INFO query - >>> All queries took 8ms:
14:46:09.069 [tp-1029120287-4] INFO query - Exec query "SELECT users.id, users.firstname, users.lastname, users.email, users.locale, users.timezone, users.password_pw, users.password_slt, users.account_id, users.superuser, users.uniqueid, users.validated FROM users WHERE id = 2 (scale -5)" : org.postgresql.jdbc4.Jdbc4ResultSet@77f31432 took 4ms
14:46:09.069 [tp-1029120287-4] INFO query
- <<< End queries

Note the same resultset. The postgres logs also shows that only a single
statement is executed....

So, what did I miss?

/Jeppe

[Derek Chen-Becker]

I'm not sure how that could be getting logged twice, especially since it's the exact same ResultSet being returned. When I tested this on my local app (against both PG and MySQL) I didn't get this behavior, but I'll try pulling from master and testing again just in case something changed.

Derek

[harryh]

I'm also seeing this double logging behavior (using PostgreSQL. I was
under the impression that it was happening because the SQL statement
is first prepared, and then executed (each of which cause a log
entry). It's not critical or anything, but it would be nice if this
could be fixed at some point.

-harryh

[Derek Chen-Becker]

OK, I'm seeing the same thing here. I'll open an issue and work on it.

Derek

[Jonathan Ferguson]

Is this related to a previous query dated 15 Sept, the title was 

[Lift] Mapper: Why is every SQL query sent twice? (second time with NULL parameters)

The response from @dpp was 

"The SQL is not being sent twice.  There are two different points (when the Statement is created and after the Statement is executed) that the same query is logged."

Cheers 

Jono

2009/10/14 Derek Chen-Becker <dchen...@gmail.com>

[Derek Chen-Becker]

I don't think so. In this case I'm seeing a ResultSet in both log entries, which shouldn't show up in the part where it's being prepared.

Derek

[Derek Chen-Becker]

OK, I found what's happening. Logging is getting called in the private DB.runPreparedStatement, and also in the DB.exec method. Mapper uses exec within the runPreparedStatement call. It seems like exec is the more appropriate place to be running the logging, since you could have multiple execs on a prepared statement but you generally wouldn't prepare a statement without executing it. Thoughts on removing the logging from runPreparedStatement?

Derek

[Derek Chen-Becker]

Another option that I just thought of would be to add a "logged" flag on the PreparedStatement wrapper so that it knows not to print a dup.

Derek

[Viktor Klang]

I vote for DB.exec

--
Viktor Klang

Blog: klangism.blogspot.com
Twttr: viktorklang
Wave: viktor...@googlewave.com
Code: github.com/viktorklang

AKKA Committer - akkasource.org
Lift Committer - liftweb.com
Atmosphere Committer - atmosphere.dev.java.net
SoftPub founder: http://groups.google.com/group/softpub

[Derek Chen-Becker]

That's +2 to removing the logging from runPreparedStatement? Any other feelings one way or the other?

Derek