This builds on and replaces Lee's PR #620. It fixes #615 through the following approach:
Firstly there are two log files:
drafter.log archives every 500 MB of raw logs into 10 .gz files.
sparql.log archives every 500 MB of raw logs into 30 .gz files.
These have different policies and purposes associated with them.
drafter.log
This log aims to provide the main summary / narrative of the whatever drafter is doing. The bulk of its contents should typically be the narrative around requests and jobs. Though it will also include initialisation messages etc. With this PR drafter.log won't contain the contents of any SPARQL queries.
sparql.log
This log contains SPARQL queries, and SPARQL updates.
This PR also contains changes which mean that by default we only log cache misses in the sparql.log. The reasoning here is that most of our queries are duplicates, so we can save some space and delay rotation longer by not logging the dupes. Stash hits should always return the same results anyway.
A SPARQL miss (against the public endpoint) looks like this in the logs:
2022-09-12T16:35:40,309 INFO sparql 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=42fcc128} :: Stasher miss key: 828afb3e6717edbbeac962aacf715fa1 for tuple query:
SELECT *
WHERE
{ ?s ?p ?o }
LIMIT 13
All misses contain the stasher key; so if we later discover something is wrong with a stash hit, we can search the cache key we report for the hit in the drafter.log. A hit for the same query above can be found in the drafter.log and looks like this:
2022-09-12T16:42:32,465 INFO stasher 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=82148544} :: Stasher hit key: 828afb3e6717edbbeac962aacf715fa1 for tuple query (elided)
What if we've rotated the sparql.log so we no longer have a miss for a query?
This is no longer a problem, as I've made some code changes so that the queries are logged to the appropriate logs at two levels (info and debug). Hence if given a hash like 828afb3e6717edbbeac962aacf715fa1 and you want to discover what query it corresponds to you can simply change the level of drafter.rdf.sparql to debug in the log4j2.xml file on the production server.
This file is reloaded every 30 seconds, so after the changes are applied; recreate the action which you are debugging, and you will find the queries are now logged temporarily to the sparql.log for cache hits too. Just remember to set the flag back, as we will be logging many more duplicate queries, and consequently rotate this file quicker.
Sample output
Querying a draftset with a cached query
drafter.log output is currently, with nothing in sparql.log:
2022-09-12T17:56:19,768 INFO logging {reqId=2581399c} :: REQUEST /v1/draftset/48d1c79b-2b5f-4a02-a0b8-5ca626177eec/query text/csv {:query "<scrubbed>", :union-with-live "false"}
2022-09-12T17:56:20,063 INFO stasher 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=2581399c} :: Stasher hit key: f6ed5e0c337378d1d7bb460b919745f5 for boolean query (elided)
2022-09-12T17:56:20,077 INFO stasher 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=2581399c} :: Stasher hit key: 7c7020fb2af17cf65c485e49457fa30c for tuple query (elided)
2022-09-12T17:56:20,107 INFO stasher 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=2581399c} :: Stasher hit key: 1d2cac4ddbd34a63b442e085557e9fdc for tuple query (elided)
2022-09-12T17:56:20,127 INFO stasher 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=2581399c} :: Stasher hit key: 1d2cac4ddbd34a63b442e085557e9fdc for tuple query (elided)
2022-09-12T17:56:20,290 INFO stasher 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=2581399c} :: Stasher hit key: 16443e7c5aab211f4bf6e73b18292188 for tuple query (elided)
2022-09-12T17:56:20,291 INFO stasher 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=2581399c} :: Stasher hit key: de5f4bd4425f796cfeb996652bf35260 for tuple query (elided)
2022-09-12T17:56:20,294 INFO logging {reqId=2581399c} :: RESPONSE 200 headers sent after 576ms streaming body...
Creating a new draftset
drafter.log is:
2022-09-12T17:58:08,430 INFO logging {reqId=cf0e158e} :: REQUEST /v1/draftsets application/json {:display-name "test", :description "blah blah", :union-with-live "false"}
2022-09-12T17:58:08,503 INFO write-scheduler 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=cf0e158e} :: Submitting sync job: {:id #uuid "de5f0f4c-4566-457d-8aed-75d39b22c81a", :user-id 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients, :status :pending, :priority :blocking-write, :start-time 1663001888495, :finish-time nil, :draftset-id nil, :draft-graph-id nil, :metadata {:draftset nil, :operation create-draftset}, :function #function[drafter.async.jobs/wrap-logging-context/fn--29318], :value-p #promise[{:status :pending, :val nil} 0xa7aa932]}
2022-09-12T17:58:09,352 INFO stasher 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {jobId=de5f0f4c, reqId=cf0e158e} :: Using new state graph last modified of: 2022-09-12T17:58:09.351+01:00_http://publishmydata.com/def/drafter/version/a2d796b3-93a2-4c18-9616-6f166ff215b3
2022-09-12T17:58:09,356 INFO logging {reqId=cf0e158e} :: RESPONSE 303 finished. It took 933ms to execute
2022-09-12T17:58:09,378 INFO logging {reqId=2dfabddb} :: REQUEST /v1/draftset/1d90c10b-7fc0-4a15-a0b2-545b013876ca application/json {}
2022-09-12T17:58:09,508 INFO stasher 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=2dfabddb} :: Stasher miss key: 40e72acc2077b35fffd44cabc31cca1a for boolean query
2022-09-12T17:58:09,652 INFO stasher 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=2dfabddb} :: Stasher miss key: a2f549f56541a8cc16df56f1e261e4a0 for tuple query
2022-09-12T17:58:09,724 INFO stasher 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=2dfabddb} :: Stasher miss key: 1bc8919988ae68388985e39d5289c72c for tuple query
2022-09-12T17:58:09,729 INFO logging {reqId=2dfabddb} :: RESPONSE 200 finished. It took 351ms to execute
sparql.log is:
2022-09-12T17:58:09,508 INFO sparql 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=2dfabddb} :: Stasher miss key: 40e72acc2077b35fffd44cabc31cca1a for boolean query:
ASK WHERE { GRAPH <http://publishmydata.com/graphs/drafter/drafts> { <http://publishmydata.com/def/drafter/draftset/1d90c10b-7fc0-4a15-a0b2-545b013876ca> a <http://publishmydata.com/def/drafter/DraftSet> . }}
2022-09-12T17:58:09,653 INFO sparql 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=2dfabddb} :: Stasher miss key: a2f549f56541a8cc16df56f1e261e4a0 for tuple query:
SELECT * WHERE { GRAPH <http://publishmydata.com/graphs/drafter/drafts> { ?ds <http://purl.org/dc/terms/created> ?created .?ds <http://purl.org/dc/terms/modified> ?modified .?ds <http://publishmydata.com/def/drafter/version> ?version .?ds <http://purl.org/dc/terms/creator> ?creator .OPTIONAL { ?ds <http://www.w3.org/2000/01/rdf-schema#comment> ?description . }OPTIONAL { ?ds <http://publishmydata.com/def/drafter/hasOwner> ?owner . }OPTIONAL { ?ds <http://www.w3.org/2000/01/rdf-schema#label> ?title . }OPTIONAL { ?ds <http://publishmydata.com/def/drafter/submittedBy> ?submitter. }OPTIONAL { ?ds <http://publishmydata.com/def/drafter/hasSubmission> ?submission . ?submission <http://publishmydata.com/def/drafter/claimUser> ?claimuser .}OPTIONAL { ?ds <http://publishmydata.com/def/drafter/hasSubmission> ?submission . ?submission <http://publishmydata.com/def/drafter/claimPermission> ?permission .}OPTIONAL { SELECT ?ds (GROUP_CONCAT(?p; SEPARATOR=" ") AS ?viewpermissions) WHERE { ?ds <http://publishmydata.com/def/drafter/viewPermission> ?p } GROUP BY ?ds}OPTIONAL { SELECT ?ds (GROUP_CONCAT(?u; SEPARATOR=" ") AS ?viewusers) WHERE { ?ds <http://publishmydata.com/def/drafter/viewUser> ?u } GROUP BY ?ds}{ SELECT DISTINCT ?ds WHERE { ?ds <http://www.w3.org/1999/02/22-rdf-syntax-ns#type> <http://publishmydata.com/def/drafter/DraftSet> . { VALUES ?ds { <http://publishmydata.com/def/drafter/draftset/1d90c10b-7fc0-4a15-a0b2-545b013876ca> } } }} }}
2022-09-12T17:58:09,725 INFO sparql 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=2dfabddb} :: Stasher miss key: 1bc8919988ae68388985e39d5289c72c for tuple query:
SELECT * WHERE { GRAPH <http://publishmydata.com/graphs/drafter/drafts> { ?ds <http://www.w3.org/1999/02/22-rdf-syntax-ns#type> <http://publishmydata.com/def/drafter/DraftSet> .?dg <http://publishmydata.com/def/drafter/inDraftSet> ?ds .?lg <http://www.w3.org/1999/02/22-rdf-syntax-ns#type> <http://publishmydata.com/def/drafter/ManagedGraph> .?lg <http://publishmydata.com/def/drafter/hasDraft> ?dg .?lg <http://publishmydata.com/def/drafter/isPublic> ?public .{ SELECT DISTINCT ?ds WHERE { ?ds <http://www.w3.org/1999/02/22-rdf-syntax-ns#type> <http://publishmydata.com/def/drafter/DraftSet> .{ VALUES ?ds { <http://publishmydata.com/def/drafter/draftset/1d90c10b-7fc0-4a15-a0b2-545b013876ca> } } }} }}
Appending a triple to a draftset
drafter.log:
2022-09-12T18:00:30,921 INFO logging {reqId=d3e12944} :: REQUEST /v1/draftset/1d90c10b-7fc0-4a15-a0b2-545b013876ca/data application/json {:graph "http://1"}
2022-09-12T18:00:30,938 INFO stasher 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=d3e12944} :: Stasher hit key: 40e72acc2077b35fffd44cabc31cca1a for boolean query (elided)
2022-09-12T18:00:31,071 INFO stasher 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=d3e12944} :: Stasher miss key: 82ac4172d0390098634e4eda83b563a5 for tuple query
2022-09-12T18:00:31,147 INFO stasher 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=d3e12944} :: Stasher hit key: a2f549f56541a8cc16df56f1e261e4a0 for tuple query (elided)
2022-09-12T18:00:31,160 INFO stasher 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=d3e12944} :: Stasher hit key: 1bc8919988ae68388985e39d5289c72c for tuple query (elided)
2022-09-12T18:00:31,183 INFO write-scheduler 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=d3e12944} :: Submitting async job: {:id #uuid "e91bc7ff-f6dd-445f-9c33-08fb0c546fdc", :user-id 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients, :status :pending, :priority :background-write, :start-time 1663002031174, :finish-time nil, :draftset-id #drafter.draftset.DraftsetId{:id 1d90c10b-7fc0-4a15-a0b2-545b013876ca}, :draft-graph-id nil, :metadata {:draftset {:description blah blah, :updated-at #object[java.time.OffsetDateTime 0x5443948b 2022-09-12T16:58:08.508Z], :type Draftset, :current-owner 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients, :created-by 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients, :id 1d90c10b-7fc0-4a15-a0b2-545b013876ca, :display-name test, :changes {}, :version #object[java.net.URI 0x46e7c5bc http://publishmydata.com/def/drafter/version/d4396bdc-56bf-48ef-85a2-937a9ec71153], :created-at #object[java.time.OffsetDateTime 0x49a0eaab 2022-09-12T16:58:08.508Z]}, :operation append-data-to-draftset}, :function #function[drafter.async.jobs/wrap-logging-context/fn--29318], :value-p #promise[{:status :pending, :val nil} 0x455f1d39]}
2022-09-12T18:00:31,194 INFO write-scheduler 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients {reqId=d3e12944} :: Queueing job: {:id #uuid "e91bc7ff-f6dd-445f-9c33-08fb0c546fdc", :user-id 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients, :status :pending, :priority :background-write, :start-time 1663002031174, :finish-time nil, :draftset-id #drafter.draftset.DraftsetId{:id 1d90c10b-7fc0-4a15-a0b2-545b013876ca}, :draft-graph-id nil, :metadata {:draftset {:description blah blah, :updated-at #object[java.time.OffsetDateTime 0x5443948b 2022-09-12T16:58:08.508Z], :type Draftset, :current-owner 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients, :created-by 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients, :id 1d90c10b-7fc0-4a15-a0b2-545b013876ca, :display-name test, :changes {}, :version #object[java.net.URI 0x46e7c5bc http://publishmydata.com/def/drafter/version/d4396bdc-56bf-48ef-85a2-937a9ec71153], :created-at #object[java.time.OffsetDateTime 0x49a0eaab 2022-09-12T16:58:08.508Z]}, :operation append-data-to-draftset}, :function #function[drafter.async.jobs/wrap-logging-context/fn--29318], :value-p #promise[{:status :pending, :val nil} 0x455f1d39]} {:reqId d3e12944, :method :put, :route /draftset/:id/data}
2022-09-12T18:00:31,198 INFO logging {reqId=d3e12944} :: RESPONSE 202 finished. It took 278ms to execute
2022-09-12T18:00:31,201 INFO stasher {jobId=e91bc7ff, reqId=d3e12944} :: Stasher hit key: 1bc8919988ae68388985e39d5289c72c for tuple query (elided)
2022-09-12T18:00:31,528 INFO stasher {jobId=e91bc7ff, reqId=d3e12944} :: Stasher miss key: 9a0cd811ce09322cc308640e4cbb7d92 for boolean query
2022-09-12T18:00:31,621 INFO stasher {jobId=e91bc7ff, reqId=d3e12944} :: Stasher miss key: 92f698c29aade0b27c6ab674296c30ab for boolean query
2022-09-12T18:00:31,780 INFO stasher {jobId=e91bc7ff, reqId=d3e12944} :: Using new state graph last modified of: 2022-09-12T18:00:31.779+01:00_http://publishmydata.com/def/drafter/version/bee78a5f-28f0-4353-983a-4c83ac49d144
2022-09-12T18:00:31,786 INFO common {jobId=e91bc7ff, reqId=d3e12944} :: Acquired lock for :copy-graph
2022-09-12T18:00:32,060 INFO stasher {jobId=e91bc7ff, reqId=d3e12944} :: Using new state graph last modified of: 2022-09-12T18:00:32.059+01:00_http://publishmydata.com/def/drafter/version/5322c398-ef51-48f7-bb44-09edd68bed13
2022-09-12T18:00:32,060 INFO common {jobId=e91bc7ff, reqId=d3e12944} :: Releasing lock for :copy-graph
2022-09-12T18:00:32,079 INFO write-scheduler {jobId=e91bc7ff, reqId=d3e12944} :: Queueing job: {:id #uuid "e91bc7ff-f6dd-445f-9c33-08fb0c546fdc", :user-id 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients, :status :pending, :priority :background-write, :start-time 1663002032061, :finish-time nil, :draftset-id #drafter.draftset.DraftsetId{:id 1d90c10b-7fc0-4a15-a0b2-545b013876ca}, :draft-graph-id nil, :metadata {:draftset {:description blah blah, :updated-at #object[java.time.OffsetDateTime 0x5443948b 2022-09-12T16:58:08.508Z], :type Draftset, :current-owner 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients, :created-by 3aOjbCpb7AlfXLJFpHpqYZfWlI5Gl0ce@clients, :id 1d90c10b-7fc0-4a15-a0b2-545b013876ca, :display-name test, :changes {}, :version #object[java.net.URI 0x46e7c5bc http://publishmydata.com/def/drafter/version/d4396bdc-56bf-48ef-85a2-937a9ec71153], :created-at #object[java.time.OffsetDateTime 0x49a0eaab 2022-09-12T16:58:08.508Z]}, :operation append-data-to-draftset}, :function #function[clojure.core/partial/fn--5857], :value-p #promise[{:status :pending, :val nil} 0x455f1d39]} {:reqId d3e12944, :method :put, :route /draftset/:id/data}
2022-09-12T18:00:32,080 INFO write-scheduler {jobId=e91bc7ff, reqId=d3e12944} :: task took 885ms
2022-09-12T18:00:32,144 INFO stasher {jobId=e91bc7ff, reqId=d3e12944} :: Using new state graph last modified of: 2022-09-12T18:00:32.144+01:00_http://publishmydata.com/def/drafter/version/19ecf0c9-2f7b-4a19-bf73-282c1b891b23
2022-09-12T18:00:32,977 INFO stasher {jobId=e91bc7ff, reqId=d3e12944} :: Using new state graph last modified of: 2022-09-12T18:00:32.977+01:00_http://publishmydata.com/def/drafter/version/aec1bfa5-c454-4d0b-9aa7-44b01ce5641d
2022-09-12T18:00:33,031 INFO stasher {jobId=e91bc7ff, reqId=d3e12944} :: Stasher miss key: 1bc8919988ae68388985e39d5289c72c for tuple query
2022-09-12T18:00:33,052 INFO stasher {jobId=e91bc7ff, reqId=d3e12944} :: Stasher miss key: 94f9b16da1528220a2324aeb03a848cd for boolean query
2022-09-12T18:00:33,090 INFO stasher {jobId=e91bc7ff, reqId=d3e12944} :: Using new state graph last modified of: 2022-09-12T18:00:33.090+01:00_http://publishmydata.com/def/drafter/version/1284ad45-95e0-48e1-9eee-b86322c4a26c
2022-09-12T18:00:33,262 INFO stasher {jobId=e91bc7ff, reqId=d3e12944} :: Using new state graph last modified of: 2022-09-12T18:00:33.262+01:00_http://publishmydata.com/def/drafter/version/f67c8a93-9e57-48bf-a2fd-a761aa3176be
2022-09-12T18:00:33,338 INFO stasher {jobId=e91bc7ff, reqId=d3e12944} :: Using new state graph last modified of: 2022-09-12T18:00:33.338+01:00_http://publishmydata.com/def/drafter/version/9bdef813-d8bb-4367-a6da-6101507c17ce
2022-09-12T18:00:33,389 INFO stasher {jobId=e91bc7ff, reqId=d3e12944} :: Using new state graph last modified of: 2022-09-12T18:00:33.389+01:00_http://publishmydata.com/def/drafter/version/225c4998-5821-431a-b971-b0cd34231845
2022-09-12T18:00:33,392 INFO write-scheduler {jobId=e91bc7ff, reqId=d3e12944} :: task took 1312ms
This builds on and replaces Lee's PR #620. It fixes #615 through the following approach:
Firstly there are two log files:
.gz
files..gz
files.These have different policies and purposes associated with them.
drafter.log
This log aims to provide the main summary / narrative of the whatever drafter is doing. The bulk of its contents should typically be the narrative around requests and jobs. Though it will also include initialisation messages etc. With this PR
drafter.log
won't contain the contents of any SPARQL queries.sparql.log
This log contains SPARQL queries, and SPARQL updates.
This PR also contains changes which mean that by default we only log cache misses in the
sparql.log
. The reasoning here is that most of our queries are duplicates, so we can save some space and delay rotation longer by not logging the dupes. Stash hits should always return the same results anyway.A SPARQL miss (against the public endpoint) looks like this in the logs:
All misses contain the stasher key; so if we later discover something is wrong with a stash hit, we can search the cache key we report for the hit in the
drafter.log
. A hit for the same query above can be found in thedrafter.log
and looks like this:What if we've rotated the
sparql.log
so we no longer have a miss for a query?This is no longer a problem, as I've made some code changes so that the queries are logged to the appropriate logs at two levels (
info
anddebug
). Hence if given a hash like828afb3e6717edbbeac962aacf715fa1
and you want to discover what query it corresponds to you can simply change thelevel
ofdrafter.rdf.sparql
todebug
in thelog4j2.xml
file on the production server.This file is reloaded every 30 seconds, so after the changes are applied; recreate the action which you are debugging, and you will find the queries are now logged temporarily to the
sparql.log
for cache hits too. Just remember to set the flag back, as we will be logging many more duplicate queries, and consequently rotate this file quicker.Sample output
Querying a draftset with a cached query
drafter.log
output is currently, with nothing insparql.log
:Creating a new draftset
drafter.log
is:sparql.log
is:Appending a triple to a draftset
drafter.log
:sparql.log
:Publishing a draftset
drafter.log
:sparql.log
: