db-derby-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From John English ...@brighton.ac.uk>
Subject Re: Locking problem
Date Fri, 15 Oct 2010 17:18:51 GMT
On 07/10/2010 02:44, Bryan Pendleton wrote:
> If you can post some of that information (i.e., if it isn't too sensitive),
> I'm sure others will be glad to help you interpret what you see there.

OK, I followed your advice, and hopefully someone can help me interpret
what I'm seeing. It's a bit lengthy, so please bear with me. I seem to 
be getting somewhere, but I have a specific question at the end...

Transaction ID 195244150 tries to delete someone from the registrations
table:

2010-10-15 15:46:18.543 GMT SunJsseListener2-1 (XID = 195244150), 
(SESSIONID = 924), (DATABASE = /home/je/db), (DRDAID = null), Executing 
prepared statement: DELETE FROM registrations WHERE username=? AND 
groupname=? :End prepared statement with 2 parameters begin parameter 
#1: XYZ :end parameter begin parameter #2: ABC :end parameter

The associated cleanup trigger then fires:

2010-10-15 15:46:18.545 GMT SunJsseListener2-1 (XID = 195244150), 
(SESSIONID = 924), (DATABASE = /home/je/db), (DRDAID = null), Executing 
prepared statement: DELETE FROM users
     WHERE username NOT IN (SELECT username FROM registrations)
     AND   username NOT IN (SELECT username FROM passwords)
     AND   username NOT IN (SELECT username FROM managers) :End prepared 
statement

It fails:

2010-10-15 15:47:18.567 GMT SunJsseListener2-1 (XID = 195244150), 
(SESSIONID = 924), (DATABASE = /home/je/db), (DRDAID = null), Cleanup 
action starting
2010-10-15 15:47:18.567 GMT SunJsseListener2-1 (XID = 195244150), 
(SESSIONID = 924), (DATABASE = /home/je/db), (DRDAID = null), Failed 
Statement is: DELETE FROM registrations WHERE username=? AND groupname=? 
with 2 parameters begin parameter #1: XYZ :end parameter begin parameter 
#2: ABC :end parameter
2010-10-15 15:47:18.569 GMT SunJsseListener2-1 (XID = 195244150), 
(SESSIONID = 924), (DATABASE = /home/je/db), (DRDAID = null), Rolling back
2010-10-15 15:47:18.590 GMT SunJsseListener2-1 (XID = 195244150), 
(SESSIONID = 923), (DATABASE = /home/je/db), (DRDAID = null), Rolling back
Cleanup action completed
ERROR 40XL2: A lock could not be obtained within the time requested. 
The lockTable dump is:
2010-10-15 15:47:18.550 GMT
*** The following row is the victim ***
195244150 |TABLE |X   |0 |Tablelock |WAIT |T |NULL |PASSWORDS
*** The above row is the victim ***
195244150 |ROW   |X   |5 |(14,8)    |GRANT|T |NULL |REGISTRATIONS
195244150 |TABLE |IS  |1 |Tablelock |GRANT|T |NULL |MANAGERS
195244150 |ROW   |X   |1 |(17,26)   |GRANT|T |NULL |USERS
195235766 |TABLE |IS  |1 |Tablelock |GRANT|T |NULL |PASSWORDS
195244150 |TABLE |IS  |1 |Tablelock |GRANT|T |NULL |PASSWORDS
195244150 |ROW   |X   |1 |(16,27)   |GRANT|T |NULL |USERS
195244150 |ROW   |X   |1 |(12,83)   |GRANT|T |NULL |USERS
195244150 |TABLE |IX  |2 |Tablelock |GRANT|T |NULL |USERS
195244150 |ROW   |X   |1 |(20,8)    |GRANT|T |NULL |USERS
195244150 |ROW   |X   |1 |(9,130)   |GRANT|T |NULL |USERS
195244150 |TABLE |IX  |5 |Tablelock |GRANT|T |NULL |REGISTRATIONS
195244150 |TABLE |IS  |1 |Tablelock |GRANT|T |NULL |REGISTRATIONS
195244150 |ROW   |X   |1 |(18,41)   |GRANT|T |NULL |USERS

All the above relates to transaction 195244150 except for the table
lock on the passwords table, id 195235766, which appears only once:

2010-10-15 12:33:55.028 GMT SunJsseListener2-0 (XID = 195235766), 
(SESSIONID = 6), (DATABASE = /home/je/db), (DRDAID = null), Executing 
prepared statement: SELECT password FROM passwords WHERE username=? :End 
prepared statement with 1 parameters begin parameter #1: PQR :end parameter

As for session ID = 6, all I find is this:

2010-10-15 06:02:07.117 GMT Thread[main,5,main] (XID = 195227758), 
(SESSIONID = 6), (DATABASE = /home/je/db), (DRDAID = null), Committing

I don't understand what it's committing here -- this is at system
startup...

2010-10-15 12:31:52.927 GMT SunJsseListener2-0 (XID = 195235558), 
(SESSIONID = 6), (DATABASE = /home/je/db), (DRDAID = null), Begin 
compiling prepared statement: SELECT password FROM passwords WHERE 
username=? :End prepared statement
2010-10-15 12:31:52.931 GMT SunJsseListener2-0 (XID = 195235558), 
(SESSIONID = 6), (DATABASE = /home/je/db), (DRDAID = null), End 
compiling prepared statement: SELECT password FROM passwords WHERE 
username=? :End prepared statement
2010-10-15 12:31:52.934 GMT SunJsseListener2-0 (XID = 195235558), 
(SESSIONID = 6), (DATABASE = /home/je/db), (DRDAID = null), Executing 
prepared statement: SELECT password FROM passwords WHERE username=? :End 
prepared statement with 1 parameters begin parameter #1: DEF :end parameter
2010-10-15 12:31:57.615 GMT SunJsseListener2-4 (XID = 195235558), 
(SESSIONID = 6), (DATABASE = /home/je/db), (DRDAID = null), Committing
2010-10-15 12:31:57.616 GMT SunJsseListener2-4 (XID = 195235566), 
(SESSIONID = 6), (DATABASE = /home/je/db), (DRDAID = null), Executing 
prepared statement: SELECT password FROM passwords WHERE username=? :End 
prepared statement with 1 parameters begin parameter #1: PQR :end parameter
2010-10-15 12:32:24.062 GMT SunJsseListener2-0 (XID = 195235566), 
(SESSIONID = 6), (DATABASE = /home/je/db), (DRDAID = null), Committing
2010-10-15 12:32:24.062 GMT SunJsseListener2-0 (XID = 195235752), 
(SESSIONID = 6), (DATABASE = /home/je/db), (DRDAID = null), Executing 
prepared statement: SELECT password FROM passwords WHERE username=? :End 
prepared statement with 1 parameters begin parameter #1: PQR :end parameter
2010-10-15 12:32:40.286 GMT SunJsseListener2-0 (XID = 195235752), 
(SESSIONID = 6), (DATABASE = /home/je/db), (DRDAID = null), Committing
2010-10-15 12:32:40.286 GMT SunJsseListener2-0 (XID = 195235759), 
(SESSIONID = 6), (DATABASE = /home/je/db), (DRDAID = null), Executing 
prepared statement: SELECT password FROM passwords WHERE username=? :End 
prepared statement with 1 parameters begin parameter #1: PQR :end parameter
2010-10-15 12:33:55.028 GMT SunJsseListener2-0 (XID = 195235759), 
(SESSIONID = 6), (DATABASE = /home/je/db), (DRDAID = null), Committing
2010-10-15 12:33:55.028 GMT SunJsseListener2-0 (XID = 195235766), 
(SESSIONID = 6), (DATABASE = /home/je/db), (DRDAID = null), Executing 
prepared statement: SELECT password FROM passwords WHERE username=? :End 
prepared statement with 1 parameters begin parameter #1: PQR :end parameter

Now the system log records failed login attempts for PQR at 12:31:57,
12:32:24, 12:32:40 and 12:33:55, followed finally by a successful login
at 12:34:10 when he finally managed to remember his password.

What I don't understand is why each of the transactions for the failed
logins don't commit until the next failed login attempt -- and in the
case where the last failure is followed by a successful login, the
transaction *never* commits.

The password validation code involves an LDAP lookup of username and
password; if this succeeds, fine, otherwise it tries to look in the 
local database instead (to allow for "local" users who are not in the
central LDAP registry), like this:

     try {
       password = new String(algo.digest(password.getBytes("UTF-8")));
       ResultSet r = db.dbQuery(Query.selectPassword,
                                new String[] { user });
       if (r.next()) {
         String dbpw = new String(r.getBytes("password"));
         r.close();
         return dbpw.equals(password);
       }
     }
     catch (SQLException e) { }
     catch (UnsupportedEncodingException e) { }
     return false;

Obviously there must be something wrong with this code, but I cannot
see what it is. Should I perhaps be closing the (empty) result set to
commit the transaction?

----------------------------------------------------------------------
  John English              | mailto:je@brighton.ac.uk
  Senior Lecturer           | http://www.it.bton.ac.uk/staff/je
  School of Computing & MIS | "Those who don't know their history
  University of Brighton    |  are condemned to relive it" (Santayana)
----------------------------------------------------------------------

Mime
View raw message