Debugging a server problem
I'm going to try to capture some of the diagnostic tools Ahmed and I used to debug Issue #57.
The server logging is controlled by the file agent/conf/logback.xml. Since Issue #57 is related to a pub operation we wanted to up the debug level for the pub processing, so we changed the log level for pubs in logbook.xml by setting:
<logger name="Model.pub" level="DEBUG" />
Then restarting the server and rerunning the test showed the following debug logs for the issue:
[info] c.i.p.UserSession$ - [incoming]: {"payload":{"cts":1451415927467,"path":["foo"],"deletePath":false,"data":"value"},"kind":"pub","closure":1,"version":14}
[debug] Model.pub - ENTRY: Received pub for path foo by user 465b647c-b5c1-47ca-9a56-78e87abb54bd. Data = Some(value) deletePath = false ACL = None
[debug] Model.pub - [getPathInfo]: Getting ACL info for path foo and parent path
[debug] Model.pub - [corePub]: ACL for path foo: create: Set($creator, 465b647c-b5c1-47ca-9a56-78e87abb54bd), read: Set($world), update: Set($creator, 465b647c-b5c1-47ca-9a56-78e87abb54bd), delete: Set($creator, 465b647c-b5c1-47ca-9a56-78e87abb54bd), permission: Set($creator, 465b647c-b5c1-47ca-9a56-78e87abb54bd)
[debug] Model.pub - [corePub]: validating ACL for UPDATE operation: path foo
[debug] Model.pub - [corePub]: ACL checks passed for user 465b647c-b5c1-47ca-9a56-78e87abb54bd to pub on path foo
[debug] Model.pub - [corePub]: Inserting pub in log for path foo
[debug] Model.pub - [corePub]: Updating latest table for path foo
[info] c.i.p.UserSession$ - [onError]: Benign non-fatal exception, session will get closed org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "latest_path_aclid_key"
Detail: Key (path, aclid)=(foo, $publicReadable) already exists.
This was helpful to find the general part of the code that encountered the error. However, right after this debug message, the code performs the update one of three different ways depending on results of earlier processing.
So now we need to know exactly which DB operation was performed.
You can get postgres to log all the statements performed on the db, and this can be very helpful in diagnosing problems. To do this, you need to modify a file called postgresql.conf. This file lives in the data directory for postgres. If you installed postgres with brew, the data directory is '/usr/local/var/postgres'.
In postgresql.conf, look for a line (or add it) that sets the value for log_statement. In my version of postgres, the line was there but commented out:
#log_statement = 'all' # none, ddl, mod, all
Uncomment this line (or add it) and make sure the value is set to 'all'. Then restart postgres and it will log all statements to the file server.log (in that same directory).
Using this approach, we could see the exact statements that were executed related to Issue #57.
LOG: execute <unnamed>: BEGIN
LOG: execute <unnamed>: SELECT * FROM latest LEFT JOIN acls USING (aclid) WHERE latest.path = $1 ORDER BY vts DESC
DETAIL: parameters: $1 = 'foo'
LOG: execute <unnamed>: INSERT INTO log (cts,isdeleted,aclid,path1) VALUES ($1, $2, $3, $4) RETURNING vts
DETAIL: parameters: $1 = '1451415927467', $2 = 'f', $3 = '$publicReadable', $4 = 'foo'
LOG: execute <unnamed>: SELECT * FROM logmeta
LOG: execute <unnamed>: UPDATE latest set vts = $1, cts = $2, data = $3, isdeleted = $4, aclid = $5 WHERE cts < $6 and path = $7
DETAIL: parameters: $1 = '16811', $2 = '1451415927467', $3 = 'value', $4 = 'f', $5 = '$publicReadable', $6 = '1451415927467', $7 = 'foo'
ERROR: duplicate key value violates unique constraint "latest_path_aclid_key"
DETAIL: Key (path, aclid)=(foo, $publicReadable) already exists.
STATEMENT: UPDATE latest set vts = $1, cts = $2, data = $3, isdeleted = $4, aclid = $5 WHERE cts < $6 and path = $7
LOG: execute S_2: ROLLBACK
From this, we see that the statement causing the error was:
execute <unnamed>: UPDATE latest set vts = $1, cts = $2, data = $3, isdeleted = $4, aclid = $5 WHERE cts < $6 and path = $7
DETAIL: parameters: $1 = '16811', $2 = '1451415927467', $3 = 'value', $4 = 'f', $5 = '$publicReadable', $6 = '1451415927467', $7 = 'foo'
Examining the three possible paths, we can see that this corresponds to the third path:
case _ => DBQueries.updateLatest(connection,vts,ctsVal,path,newData,deletePath,newACL).executeUpdate()
Now to determine why this is a problem.
You can look at what is currently in the database using the psql utility:
[mkistler@MKistlers-MacBook-Pro] ~>psql
psql (9.4.5)
Type "help" for help.
mkistler=#
We want to see what is in the latest table for the path foo:
mkistler=# select cts,vts,path1,aclid,isDeleted from latest where path1='foo' AND path2 is null;
cts | vts | path1 | aclid | isdeleted
---------------+-------+-------+-------------------------------------------------------+-----------
1451254284041 | 15926 | foo | $publicCreatable-465b647c-b5c1-47ca-9a56-78e87abb54bd | t
1451254284041 | 15927 | foo | $publicReadable | f
(2 rows)
Now we can see that the update statement that caused the error would have attempted to update both these rows, causing them both to have the same path and acl.