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:[email protected]
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)
----------------------------------------------------------------------
