add SPARQL query logging module

lib/sparql/client.rb

@@ -18,6 +18,7 @@ module SPARQL
   class Client
     autoload :Query,      'sparql/client/query'
     autoload :Cache, 'sparql/client/cache'
+    autoload :Logging, 'sparql/client/logging'
     autoload :Repository, 'sparql/client/repository'
     autoload :Update,     'sparql/client/update'
     autoload :VERSION,    'sparql/client/version'
@@ -60,6 +61,8 @@ class ServerError < StandardError; end
     XMLNS = {'sparql' => 'http://www.w3.org/2005/sparql-results#'}.freeze
 
     attr_reader :cache
+    attr_reader :logger
+
     ##
     # The SPARQL endpoint URL, or an RDF::Queryable instance, to use the native SPARQL engine.
     #
@@ -96,9 +99,9 @@ class ServerError < StandardError; end
     #   Defaults  `User-Agent` header, unless one is specified.
     # @option options [Hash] :read_timeout
     def initialize(url, **options, &block)
-      @logger = options[:logger] ||= Kernel.const_defined?("LOGGER") ? Kernel.const_get("LOGGER") : Logger.new(STDOUT)
-
       @cache = SPARQL::Client::Cache.new(redis_cache: options[:redis_cache])
+      @logger = Logging.new(redis: @cache.redis_cache,
+                            logger: options[:logger])
 
       case url
       when RDF::Queryable
@@ -330,23 +333,32 @@ def nodes
     # @raise [IOError] if connection is closed
     # @see    https://www.w3.org/TR/sparql11-protocol/#query-operation
     def query(query, **options)
-      cached_response = @cache.get(query, options)
+      cached_response = nil
+      @logger.log(query, user: options[:user]) do
+        cached_response = @cache.get(query, options)
+      end
+
       return cached_response if cached_response
 
+
       @op = :query
       @alt_endpoint = options[:endpoint]
-      case @url
-      when RDF::Queryable
-        require 'sparql' unless defined?(::SPARQL::Grammar)
-        begin
-          SPARQL.execute(query, @url, optimize: true, **options)
-        rescue SPARQL::MalformedQuery
-          $stderr.puts "error running #{query}: #{$!}"
-          raise
+      output = nil
+      @logger.log(query, user: options[:user], cached: false) do
+        case @url
+        when RDF::Queryable
+          require 'sparql' unless defined?(::SPARQL::Grammar)
+          begin
+            output = SPARQL.execute(query, @url, optimize: true, **options)
+          rescue SPARQL::MalformedQuery
+            $stderr.puts "error running #{query}: #{$!}"
+            raise
+          end
+        else
+          output = parse_response(response(query, **options), **options)
         end
-      else
-        parse_response(response(query, **options), **options)
       end
+      output
     end
 
     ##
@@ -369,12 +381,14 @@ def update(query, **options)
       end
 
       @alt_endpoint = options[:endpoint]
-      case @url
-      when RDF::Queryable
-        require 'sparql' unless defined?(::SPARQL::Grammar)
-        SPARQL.execute(query, @url, update: true, optimize: true, **options)
-      else
-        response(query, **options)
+      @logger.log(query, user: options[:user], cached: false) do
+        case @url
+        when RDF::Queryable
+          require 'sparql' unless defined?(::SPARQL::Grammar)
+          SPARQL.execute(query, @url, update: true, optimize: true, **options)
+        else
+          response(query, **options)
+        end
       end
       self
     end
@@ -740,6 +754,11 @@ def inspect
 
     def redis_cache=(redis_cache)
       @cache.redis_cache = redis_cache
+      @logger.redis = redis_cache
+    end
+
+    def logger=(logger)
+      @logger.logger =  logger
     end
 
     protected

lib/sparql/client/logging.rb

@@ -0,0 +1,77 @@
+require 'benchmark'
+class SPARQL::Client
+  class Logging
+    attr_accessor :logger
+    attr_accessor :redis
+    attr_accessor :enabled
+
+    REDIS_EXPIRY = 86_400 # 24 hours
+
+    def initialize(redis:, redis_key: 'query_logs', redis_expiry: REDIS_EXPIRY, logger: nil)
+      @redis = redis
+      @logger = logger
+      @redis_key = redis_key
+      @redis_expiry = redis_expiry
+      @enabled = !logger.nil?
+    end
+
+    def log(query, id: SecureRandom.uuid, cached: nil, user: nil ,&block)
+      return block.call unless @enabled
+
+      time = Benchmark.realtime do
+        result = block.call
+        cached = !result.nil? if cached.nil?
+      end
+      info(query, id: id, cached: cached, user: user, execution_time: time)
+    end
+
+
+    def info(query, id: SecureRandom.uuid, cached: 'null', user: 'null', execution_time: 0)
+      timestamp = Time.now.iso8601
+      entry = {
+        id: id,
+        timestamp: timestamp,
+        query: query,
+        cached: cached,
+        user: user,
+        execution_time: execution_time
+      }
+
+
+      @logger&.info("SPARQL: #{query} (#{execution_time}s) | Cached: #{cached} | User: #{user}")
+      return if @redis.nil?
+
+      key = "#{@redis_key}-#{id}-#{timestamp}"
+      entry = encode_data(entry)
+      return if entry.nil?
+
+      @redis.set(key, entry)
+      @redis.expire(key, @redis_expiry)
+    end
+
+    def get_logs
+      keys = @redis.keys("#{@redis_key}-*")
+      keys.map { |key| Marshal.load(@redis.get(key)) }
+    end
+
+    def logger=(logger)
+      @logger = logger
+      @enabled = !logger.nil?
+    end
+
+    private
+    def encode_data(entry)
+      data = Marshal.dump(entry.to_json)
+      if data.length > 50e6 # 50MB of marshal object
+        # avoid large entries to go in the cache
+        return nil
+      end
+      data
+    end
+
+    def decode_data(data)
+      Marshal.load(data)
+    end
+
+  end
+end