From ec4a6e993e28ad221e678dc6470897fb82c6f665 Mon Sep 17 00:00:00 2001
From: Nicolas Dular <ndular@gitlab.com>
Date: Tue, 16 May 2023 08:33:32 +0000
Subject: [PATCH] Add new llm logger for debugging AI features
Adds a new logger and debugging statements for AI features.
---
doc/administration/logs/index.md | 12 ++++++++++++
doc/development/ai_features.md | 9 +++++++++
ee/app/services/llm/base_service.rb | 18 ++++++++++++++++--
ee/app/workers/llm/completion_worker.rb | 14 ++++++++++++++
ee/lib/gitlab/llm/anthropic/client.rb | 11 +++++++++--
.../graphql_subscription_response_service.rb | 8 +++++++-
ee/lib/gitlab/llm/logger.rb | 11 +++++++++++
ee/lib/gitlab/llm/open_ai/client.rb | 7 ++++++-
ee/lib/gitlab/llm/vertex_ai/client.rb | 14 ++++++++++++--
9 files changed, 96 insertions(+), 8 deletions(-)
create mode 100644 ee/lib/gitlab/llm/logger.rb
diff --git a/doc/administration/logs/index.md b/doc/administration/logs/index.md
index 7fab97f76da4c..3533237f94619 100644
--- a/doc/administration/logs/index.md
+++ b/doc/administration/logs/index.md
@@ -1034,6 +1034,18 @@ can be used.
}
```
+## `llm.log` **(ULTIMATE SAAS)**
+
+> [Introduced](https://gitlab.com/gitlab-org/gitlab/-/merge_requests/120506) in GitLab 16.0.
+
+The `llm.log` file logs information related to
+[AI features](../../user/ai_features.md).
+
+Depending on your installation method, this file is located at:
+
+- Omnibus GitLab: `/var/log/gitlab/gitlab-rails/llm.log`
+- Installations from source: `/home/git/gitlab/log/llm.log`
+
## Registry logs
For Omnibus GitLab installations, Container Registry logs are in `/var/log/gitlab/registry/current`.
diff --git a/doc/development/ai_features.md b/doc/development/ai_features.md
index 6ed1d59c3e076..25da99addc1a7 100644
--- a/doc/development/ai_features.md
+++ b/doc/development/ai_features.md
@@ -89,6 +89,15 @@ To populate the embedding database for GitLab chat:
1. Open a rails console
1. Run [this script](https://gitlab.com/gitlab-com/gl-infra/production/-/issues/10588#note_1373586079) to populate the embedding database
+### Debugging
+
+To gather more insights about the full request, use the `Gitlab::Llm::Logger` file to debug logs.
+To follow the debugging messages related to the AI requests on the abstraction layer, you can use:
+
+```shell
+tail -f log/llm.log
+```
+
### Configure GCP Vertex access
In order to obtain a GCP service key for local development, please follow the steps below:
diff --git a/ee/app/services/llm/base_service.rb b/ee/app/services/llm/base_service.rb
index 4930417dae910..dac7daef38d1d 100644
--- a/ee/app/services/llm/base_service.rb
+++ b/ee/app/services/llm/base_service.rb
@@ -8,10 +8,14 @@ def initialize(user, resource, options = {})
@user = user
@resource = resource
@options = options
+ @logger = Gitlab::Llm::Logger.build
end
def execute
- return error(INVALID_MESSAGE) unless valid?
+ unless valid?
+ logger.debug(message: "Returning from Service due to validation")
+ return error(INVALID_MESSAGE)
+ end
perform
end
@@ -24,7 +28,7 @@ def valid?
private
- attr_reader :user, :resource, :options
+ attr_reader :user, :resource, :options, :logger
def perform
raise NotImplementedError
@@ -33,6 +37,16 @@ def perform
def perform_async(user, resource, action_name, options)
request_id = SecureRandom.uuid
options[:request_id] = request_id
+
+ logger.debug(
+ message: "Enqueuing CompletionWorker",
+ user_id: user.id,
+ resource_id: resource.id,
+ resource_class: resource.class.name,
+ request_id: request_id,
+ action_name: action_name
+ )
+
::Llm::CompletionWorker.perform_async(user.id, resource.id, resource.class.name, action_name, options)
success(request_id: request_id)
diff --git a/ee/app/workers/llm/completion_worker.rb b/ee/app/workers/llm/completion_worker.rb
index 3571a87134537..ad9e1163e4127 100644
--- a/ee/app/workers/llm/completion_worker.rb
+++ b/ee/app/workers/llm/completion_worker.rb
@@ -10,6 +10,13 @@ class CompletionWorker
urgency :low
def perform(user_id, resource_id, resource_class, ai_action_name, options = {})
+ logger.debug(
+ message: "Performing CompletionWorker",
+ user_id: user_id,
+ resource_id: resource_id,
+ action_name: ai_action_name
+ )
+
return unless Feature.enabled?(:openai_experimentation)
options.symbolize_keys!
@@ -23,12 +30,19 @@ def perform(user_id, resource_id, resource_class, ai_action_name, options = {})
return unless resource.send_to_ai?
params = { request_id: options.delete(:request_id) }
+
ai_completion = ::Gitlab::Llm::CompletionsFactory.completion(ai_action_name.to_sym, params)
+ logger.debug(message: "Getting Completion Service from factory", class_name: ai_completion.class.name)
+
ai_completion.execute(user, resource, options) if ai_completion
end
private
+ def logger
+ @logger ||= Gitlab::Llm::Logger.build
+ end
+
def find_resource(resource_id, resource_class)
resource_class.classify.constantize.find_by_id(resource_id)
end
diff --git a/ee/lib/gitlab/llm/anthropic/client.rb b/ee/lib/gitlab/llm/anthropic/client.rb
index edcb81c7b5789..d3bef2f51633a 100644
--- a/ee/lib/gitlab/llm/anthropic/client.rb
+++ b/ee/lib/gitlab/llm/anthropic/client.rb
@@ -13,21 +13,28 @@ class Client
def initialize(user)
@user = user
+ @logger = Gitlab::Llm::Logger.build
end
def complete(prompt:, **options)
return unless enabled?
- Gitlab::HTTP.post(
+ logger.debug("Performing request to Anthropic")
+
+ response = Gitlab::HTTP.post(
URI.join(URL, '/v1/complete'),
headers: request_headers,
body: request_body(prompt: prompt, options: options).to_json
)
+
+ logger.debug("Received response from Anthropic")
+
+ response
end
private
- attr_reader :user
+ attr_reader :user, :logger
retry_methods_with_exponential_backoff :complete
diff --git a/ee/lib/gitlab/llm/graphql_subscription_response_service.rb b/ee/lib/gitlab/llm/graphql_subscription_response_service.rb
index 829055e641941..7efe87693aa59 100644
--- a/ee/lib/gitlab/llm/graphql_subscription_response_service.rb
+++ b/ee/lib/gitlab/llm/graphql_subscription_response_service.rb
@@ -8,6 +8,7 @@ def initialize(user, resource, response_modifier, options:)
@resource = resource
@response_modifier = response_modifier
@options = options
+ @logger = Gitlab::Llm::Logger.build
end
def execute
@@ -22,12 +23,17 @@ def execute
errors: response_modifier.errors
}
+ logger.debug(
+ message: "Broadcasting AI response",
+ data: data
+ )
+
GraphqlTriggers.ai_completion_response(user.to_global_id, resource.to_global_id, data)
end
private
- attr_reader :user, :resource, :response_modifier, :options
+ attr_reader :user, :resource, :response_modifier, :options, :logger
def generate_response_body(response_body)
return response_body if options[:markup_format].nil? || options[:markup_format] == :raw
diff --git a/ee/lib/gitlab/llm/logger.rb b/ee/lib/gitlab/llm/logger.rb
new file mode 100644
index 0000000000000..32c1114b4b28f
--- /dev/null
+++ b/ee/lib/gitlab/llm/logger.rb
@@ -0,0 +1,11 @@
+# frozen_string_literal: true
+
+module Gitlab
+ module Llm
+ class Logger < ::Gitlab::JsonLogger
+ def self.file_name_noext
+ 'llm'
+ end
+ end
+ end
+end
diff --git a/ee/lib/gitlab/llm/open_ai/client.rb b/ee/lib/gitlab/llm/open_ai/client.rb
index 938b332430e0d..92d73fbdeffcc 100644
--- a/ee/lib/gitlab/llm/open_ai/client.rb
+++ b/ee/lib/gitlab/llm/open_ai/client.rb
@@ -14,6 +14,7 @@ class Client
def initialize(user, request_timeout: nil)
@user = user
@request_timeout = request_timeout
+ @logger = Gitlab::Llm::Logger.build
end
def chat(content:, moderated: nil, **options)
@@ -71,7 +72,7 @@ def moderations(input:, **options)
retry_methods_with_exponential_backoff :chat, :completions, :edits, :embeddings, :moderations
- attr_reader :user, :request_timeout
+ attr_reader :user, :request_timeout, :logger
def client
@client ||= OpenAI::Client.new(access_token: access_token, request_timeout: request_timeout)
@@ -108,10 +109,14 @@ def warn_if_moderated_unset(moderated, default:)
def request(endpoint:, moderated:, **options)
return unless enabled?
+ logger.debug(message: "Performing request to OpenAI", endpoint: endpoint)
+
moderate!(:input, moderation_input(endpoint, options)) if should_moderate?(:input, moderated)
response = client.public_send(endpoint, **options) # rubocop:disable GitlabSecurity/PublicSend
+ logger.debug(message: "Received response from OpenAI")
+
track_cost(endpoint, response.parsed_response&.dig('usage'))
if should_moderate?(:output, moderated)
diff --git a/ee/lib/gitlab/llm/vertex_ai/client.rb b/ee/lib/gitlab/llm/vertex_ai/client.rb
index f82c11ad23f86..c7cecf0a886f3 100644
--- a/ee/lib/gitlab/llm/vertex_ai/client.rb
+++ b/ee/lib/gitlab/llm/vertex_ai/client.rb
@@ -6,7 +6,9 @@ module VertexAi
class Client
include ::Gitlab::Llm::Concerns::ExponentialBackoff
- def initialize(_user); end
+ def initialize(_user)
+ @logger = Gitlab::Llm::Logger.build
+ end
# @param [String] content - Input string
# @param [Hash] options - Additional options to pass to the request
@@ -63,14 +65,22 @@ def code(content:, **options)
private
+ attr_reader :logger
+
retry_methods_with_exponential_backoff :chat, :text, :code, :messages_chat
def request(content:, config:, **options)
- HTTParty.post( # rubocop: disable Gitlab/HTTParty
+ logger.debug(message: "Performing request to Vertex", config: config)
+
+ response = HTTParty.post( # rubocop: disable Gitlab/HTTParty
config.url,
headers: config.headers,
body: config.payload(content).merge(options).to_json
)
+
+ logger.debug(message: "Received response from Vertex")
+
+ response
end
def service_name
--
GitLab