[Lift] Re: DB logging logs statements twice?

2009-10-15 Thread 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

On Wed, Oct 14, 2009 at 11:42 PM, Derek Chen-Becker
dchenbec...@gmail.comwrote:

 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


 On Tue, Oct 13, 2009 at 6:09 PM, Jonathan Ferguson j...@spiralarm.comwrote:

 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 dchenbec...@gmail.com

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

 Derek


 On Tue, Oct 13, 2009 at 10:07 AM, harryh har...@gmail.com wrote:


 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

 On Oct 13, 10:28 am, Derek Chen-Becker dchenbec...@gmail.com wrote:
  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
 
  On Tue, Oct 13, 2009 at 6:56 AM, Jeppe Nejsum Madsen 
 je...@ingolfs.dkwrote:
 
 
 
   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.jdbc4result...@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.jdbc4result...@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






 



--~--~-~--~~~---~--~~
You received this message because you are subscribed to the Google Groups 
Lift group.
To post to this group, send email to liftweb@googlegroups.com
To unsubscribe from this group, send email to 
liftweb+unsubscr...@googlegroups.com
For more options, visit this group at 
http://groups.google.com/group/liftweb?hl=en
-~--~~~~--~~--~--~---



[Lift] Re: DB logging logs statements twice?

2009-10-15 Thread 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

On Thu, Oct 15, 2009 at 8:09 AM, Derek Chen-Becker dchenbec...@gmail.comwrote:

 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


 On Wed, Oct 14, 2009 at 11:42 PM, Derek Chen-Becker dchenbec...@gmail.com
  wrote:

 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


 On Tue, Oct 13, 2009 at 6:09 PM, Jonathan Ferguson j...@spiralarm.comwrote:

 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 dchenbec...@gmail.com

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

 Derek


 On Tue, Oct 13, 2009 at 10:07 AM, harryh har...@gmail.com wrote:


 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

 On Oct 13, 10:28 am, Derek Chen-Becker dchenbec...@gmail.com wrote:
  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
 
  On Tue, Oct 13, 2009 at 6:56 AM, Jeppe Nejsum Madsen 
 je...@ingolfs.dkwrote:
 
 
 
   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.jdbc4result...@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.jdbc4result...@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






 




--~--~-~--~~~---~--~~
You received this message because you are subscribed to the Google Groups 
Lift group.
To post to this group, send email to liftweb@googlegroups.com
To unsubscribe from this group, send email to 
liftweb+unsubscr...@googlegroups.com
For more options, visit this group at 
http://groups.google.com/group/liftweb?hl=en
-~--~~~~--~~--~--~---



[Lift] Re: DB logging logs statements twice?

2009-10-15 Thread Viktor Klang
I vote for DB.exec

On Thu, Oct 15, 2009 at 4:09 PM, Derek Chen-Becker dchenbec...@gmail.comwrote:

 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


 On Wed, Oct 14, 2009 at 11:42 PM, Derek Chen-Becker dchenbec...@gmail.com
  wrote:

 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


 On Tue, Oct 13, 2009 at 6:09 PM, Jonathan Ferguson j...@spiralarm.comwrote:

 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 dchenbec...@gmail.com

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

 Derek


 On Tue, Oct 13, 2009 at 10:07 AM, harryh har...@gmail.com wrote:


 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

 On Oct 13, 10:28 am, Derek Chen-Becker dchenbec...@gmail.com wrote:
  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
 
  On Tue, Oct 13, 2009 at 6:56 AM, Jeppe Nejsum Madsen 
 je...@ingolfs.dkwrote:
 
 
 
   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.jdbc4result...@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.jdbc4result...@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










 



-- 
Viktor Klang

Blog: klangism.blogspot.com
Twttr: viktorklang
Wave: viktor.kl...@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

--~--~-~--~~~---~--~~
You received this message because you are subscribed to the Google Groups 
Lift group.
To post to this group, send email to liftweb@googlegroups.com
To unsubscribe from this group, send email to 
liftweb+unsubscr...@googlegroups.com
For more options, visit this group at 
http://groups.google.com/group/liftweb?hl=en
-~--~~~~--~~--~--~---



[Lift] Re: DB logging logs statements twice?

2009-10-15 Thread Derek Chen-Becker
That's +2 to removing the logging from runPreparedStatement? Any other
feelings one way or the other?

Derek

On Thu, Oct 15, 2009 at 8:13 AM, Viktor Klang viktor.kl...@gmail.comwrote:

 I vote for DB.exec


 On Thu, Oct 15, 2009 at 4:09 PM, Derek Chen-Becker 
 dchenbec...@gmail.comwrote:

 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


 On Wed, Oct 14, 2009 at 11:42 PM, Derek Chen-Becker 
 dchenbec...@gmail.com wrote:

 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


 On Tue, Oct 13, 2009 at 6:09 PM, Jonathan Ferguson 
 j...@spiralarm.comwrote:

 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 dchenbec...@gmail.com

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

 Derek


 On Tue, Oct 13, 2009 at 10:07 AM, harryh har...@gmail.com wrote:


 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

 On Oct 13, 10:28 am, Derek Chen-Becker dchenbec...@gmail.com wrote:
  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
 
  On Tue, Oct 13, 2009 at 6:56 AM, Jeppe Nejsum Madsen 
 je...@ingolfs.dkwrote:
 
 
 
   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.jdbc4result...@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.jdbc4result...@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














 --
 Viktor Klang

 Blog: klangism.blogspot.com
 Twttr: viktorklang
 Wave: viktor.kl...@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


 


--~--~-~--~~~---~--~~
You received this message because you are subscribed to the Google Groups 
Lift group.
To post to this group, send email to liftweb@googlegroups.com
To unsubscribe from this group, send email to 
liftweb+unsubscr...@googlegroups.com
For more options, visit this group at 

[Lift] Re: DB logging logs statements twice?

2009-10-14 Thread 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

On Tue, Oct 13, 2009 at 6:09 PM, Jonathan Ferguson j...@spiralarm.comwrote:

 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 dchenbec...@gmail.com

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

 Derek


 On Tue, Oct 13, 2009 at 10:07 AM, harryh har...@gmail.com wrote:


 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

 On Oct 13, 10:28 am, Derek Chen-Becker dchenbec...@gmail.com wrote:
  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
 
  On Tue, Oct 13, 2009 at 6:56 AM, Jeppe Nejsum Madsen je...@ingolfs.dk
 wrote:
 
 
 
   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.jdbc4result...@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.jdbc4result...@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






 


--~--~-~--~~~---~--~~
You received this message because you are subscribed to the Google Groups 
Lift group.
To post to this group, send email to liftweb@googlegroups.com
To unsubscribe from this group, send email to 
liftweb+unsubscr...@googlegroups.com
For more options, visit this group at 
http://groups.google.com/group/liftweb?hl=en
-~--~~~~--~~--~--~---



[Lift] Re: DB logging logs statements twice?

2009-10-13 Thread 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

On Tue, Oct 13, 2009 at 6:56 AM, Jeppe Nejsum Madsen je...@ingolfs.dkwrote:


 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.jdbc4result...@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.jdbc4result...@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

 


--~--~-~--~~~---~--~~
You received this message because you are subscribed to the Google Groups 
Lift group.
To post to this group, send email to liftweb@googlegroups.com
To unsubscribe from this group, send email to 
liftweb+unsubscr...@googlegroups.com
For more options, visit this group at 
http://groups.google.com/group/liftweb?hl=en
-~--~~~~--~~--~--~---



[Lift] Re: DB logging logs statements twice?

2009-10-13 Thread 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

On Oct 13, 10:28 am, Derek Chen-Becker dchenbec...@gmail.com wrote:
 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

 On Tue, Oct 13, 2009 at 6:56 AM, Jeppe Nejsum Madsen je...@ingolfs.dkwrote:



  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.jdbc4result...@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.jdbc4result...@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
--~--~-~--~~~---~--~~
You received this message because you are subscribed to the Google Groups 
Lift group.
To post to this group, send email to liftweb@googlegroups.com
To unsubscribe from this group, send email to 
liftweb+unsubscr...@googlegroups.com
For more options, visit this group at 
http://groups.google.com/group/liftweb?hl=en
-~--~~~~--~~--~--~---



[Lift] Re: DB logging logs statements twice?

2009-10-13 Thread Derek Chen-Becker
OK, I'm seeing the same thing here. I'll open an issue and work on it.

Derek

On Tue, Oct 13, 2009 at 10:07 AM, harryh har...@gmail.com wrote:


 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

 On Oct 13, 10:28 am, Derek Chen-Becker dchenbec...@gmail.com wrote:
  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
 
  On Tue, Oct 13, 2009 at 6:56 AM, Jeppe Nejsum Madsen je...@ingolfs.dk
 wrote:
 
 
 
   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.jdbc4result...@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.jdbc4result...@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
 


--~--~-~--~~~---~--~~
You received this message because you are subscribed to the Google Groups 
Lift group.
To post to this group, send email to liftweb@googlegroups.com
To unsubscribe from this group, send email to 
liftweb+unsubscr...@googlegroups.com
For more options, visit this group at 
http://groups.google.com/group/liftweb?hl=en
-~--~~~~--~~--~--~---