diff --git a/ee/app/services/remote_development/workspaces/reconcile_service.rb b/ee/app/services/remote_development/workspaces/reconcile_service.rb index ca70e50af35fbc9fe0d5e52103ec0037042d06ec..22a8fc61d0e67f533069a862d8beafc9782d89f7 100644 --- a/ee/app/services/remote_development/workspaces/reconcile_service.rb +++ b/ee/app/services/remote_development/workspaces/reconcile_service.rb @@ -1,6 +1,5 @@ # frozen_string_literal: true -# rubocop:disable Gitlab/RailsLogger module RemoteDevelopment module Workspaces class ReconcileService @@ -29,10 +28,6 @@ def execute(agent:, params:) process(agent, params) end rescue => e # rubocop:disable Style:RescueStandardError - err = "Unexpected exception. Exception class: #{e.class}. " \ - "Exception message: #{e.message.presence || '(no error message)'}" - Rails.logger.error("DEBUGGING: #{err}") - Rails.logger.error("DEBUGGING: #{e.full_message}") # TODO: If anything in the service class throws an exception, it ends up calling # #handle_api_exception, in lib/api/helpers.rb, which tries to get current_user, # which ends up calling API::Helpers#unauthorized! in lib/api/helpers.rb, @@ -43,8 +38,28 @@ def execute(agent:, params:) # in order to avoid this. # How do the other ga4k requests like starboard_vulnerability handle this? # UPDATE: See more context in https://gitlab.com/gitlab-org/gitlab/-/issues/402718#note_1343933650 + + # TODO: Not sure of standards around calling logger.error vs. Gitlab::ErrorTracking.track_exception, or the + # appropriate message/arguments to pass to each. E.g., do we have to have a separate logger.error + # call in order to get it into our dedicated json log file, or can we do this with a single + # track_exception call? + message = "Unexpected reconcile error" + logger.error( + { + message: message, + error_type: 'reconcile', + class: self.class.name, + # TODO: Is is acceptable to log the entire exception, or is this potentially exposing sensitive info? + # I see we do this other places in the codebase with other loggers. If not what is the proper way to + # capture the full error and backtrace? + error_class: e.class.name, + error_message: e.message, + backtrace: e.backtrace + } + ) + Gitlab::ErrorTracking.track_exception(e, error_type: 'reconcile', agent_id: agent.id) ServiceResponse.error( - message: err, + message: "#{message}. Exception class: #{e.class}.", reason: :internal_server_error ) end @@ -52,8 +67,6 @@ def execute(agent:, params:) private def process(agent, params) - Rails.logger.debug("DEBUGGING: Agent ID #{agent.id}") - parsed_params, error = RemoteDevelopment::Workspaces::Reconcile::ParamsParser.new.parse(params: params) return ServiceResponse.error(message: error.message, reason: error.reason) if error @@ -64,7 +77,11 @@ def process(agent, params) ServiceResponse.success(payload: payload) end + + # TODO: Dry up memoized logger factory to a shared concern + def logger + @logger ||= RemoteDevelopment::Logger.build + end end end end -# rubocop:enable Gitlab/RailsLogger diff --git a/ee/lib/remote_development/logger.rb b/ee/lib/remote_development/logger.rb new file mode 100644 index 0000000000000000000000000000000000000000..ed767b6b59d2efd81e1b3bece7d0bbed8debb46e --- /dev/null +++ b/ee/lib/remote_development/logger.rb @@ -0,0 +1,9 @@ +# frozen_string_literal: true + +module RemoteDevelopment + class Logger < ::Gitlab::JsonLogger + def self.file_name_noext + 'remote_development' + end + end +end diff --git a/ee/lib/remote_development/workspaces/create/devfile_processor.rb b/ee/lib/remote_development/workspaces/create/devfile_processor.rb index 85e2f44308ae448428a1c6bdf8a0466f096ed289..26c3d24879ff268cdef272d36aeb80285f705c4b 100644 --- a/ee/lib/remote_development/workspaces/create/devfile_processor.rb +++ b/ee/lib/remote_development/workspaces/create/devfile_processor.rb @@ -101,7 +101,6 @@ def add_editor(flattened_devfile:, editor:, volume_reference:, volume_mount_dir: end # TODO: figure out what to do when no editor injection component is found - # TODO: figure out what to do when no component is present in the flattened_devfile? if editor_component_found flattened_devfile['components'] += editor_components diff --git a/ee/lib/remote_development/workspaces/reconcile/desired_config_generator.rb b/ee/lib/remote_development/workspaces/reconcile/desired_config_generator.rb index 53d79324a2bf19017914b14c1e697e46647a6679..9453ab48bbbbdb6e5f592506e2a2bbeddc9c8637 100644 --- a/ee/lib/remote_development/workspaces/reconcile/desired_config_generator.rb +++ b/ee/lib/remote_development/workspaces/reconcile/desired_config_generator.rb @@ -15,7 +15,6 @@ def generate_desired_config(workspace:) domain_template = "{{.port}}-#{name}.#{workspace.dns_zone}" - # TODO: use owning_inventory in process_devfile workspace_inventory_config_map, owning_inventory = create_workspace_inventory_config_map(name: name, namespace: namespace, agent_id: agent.id) replicas = get_workspace_replicas(desired_state: desired_state) diff --git a/ee/lib/remote_development/workspaces/reconcile/reconcile_processor.rb b/ee/lib/remote_development/workspaces/reconcile/reconcile_processor.rb index 1b2280d6e7923059ae6ce198fb6c92663bf00402..79344683d0b8a957ab7c6d4dfa5afbc9302468c3 100644 --- a/ee/lib/remote_development/workspaces/reconcile/reconcile_processor.rb +++ b/ee/lib/remote_development/workspaces/reconcile/reconcile_processor.rb @@ -1,6 +1,5 @@ # frozen_string_literal: true -# rubocop:disable Gitlab/RailsLogger # noinspection RubyResolve module RemoteDevelopment module Workspaces @@ -8,33 +7,63 @@ module Reconcile class ReconcileProcessor include UpdateType + # rubocop:disable Metrics/AbcSize def process(agent:, workspace_agent_infos:, update_type:) - Rails.logger.debug("DEBUGGING: Beginning processing of workspace updates") - Rails.logger.debug("DEBUGGING: workspace_agent_infos: #{workspace_agent_infos.inspect}") - + logger.debug( + message: 'Beginning ReconcileProcessor', + agent_id: agent.id, + update_type: update_type + ) # parse an array of AgentInfo objects from the workspace_agent_infos array workspace_agent_infos_by_name = workspace_agent_infos.each_with_object({}) do |workspace_agent_info, hash| info = AgentInfoParser.new.parse(workspace_agent_info: workspace_agent_info) hash[info.name] = info + + next unless [States::UNKNOWN, States::ERROR].include? info.actual_state + + logger.warn( + message: 'Abnormal workspace actual_state', + error_type: 'abnormal_workspace_state', + actual_state: actual_state, + workspace_deployment_status: workspace_agent_info['latest_k8s_deployment_info'].fetch('status', {}).to_s + ) end names_from_agent_infos = workspace_agent_infos_by_name.keys - workspaces_from_agent_infos = agent.workspaces.where(name: names_from_agent_infos) # rubocop:disable CodeReuse/ActiveRecord - - check_for_orphan_workspaces(names_from_agent_infos, workspaces_from_agent_infos.map(&:name)) + logger.debug( + message: 'Parsed workspaces from workspace_agent_infos', + agent_id: agent.id, + update_type: update_type, + count: names_from_agent_infos.length, + workspace_agent_infos: workspace_agent_infos_by_name.values.map do |agent_info| + { + name: agent_info.name, + namespace: agent_info.namespace, + actual_state: agent_info.actual_state, + deployment_resource_version: agent_info.deployment_resource_version + } + end + ) + + persisted_workspaces_from_agent_infos = agent.workspaces.where(name: names_from_agent_infos) # rubocop:disable CodeReuse/ActiveRecord + + check_for_orphaned_workspaces( + workspace_agent_infos_by_name: workspace_agent_infos_by_name, + persisted_workspace_names: persisted_workspaces_from_agent_infos.map(&:name), + agent_id: agent.id, + update_type: update_type + ) # Update persisted workspaces which match the names of the workspaces in the AgentInfo objects array - workspaces_from_agent_infos.each do |workspace| - workspace_agent_info = workspace_agent_infos_by_name[workspace.name] + persisted_workspaces_from_agent_infos.each do |persisted_workspace| + workspace_agent_info = workspace_agent_infos_by_name[persisted_workspace.name] # Update the persisted workspaces with the latest info from the AgentInfo objects we received - update_existing_workspace_with_latest_info( - workspace: workspace, + update_persisted_workspace_with_latest_info( + persisted_workspace: persisted_workspace, deployment_resource_version: workspace_agent_info.deployment_resource_version, actual_state: workspace_agent_info.actual_state ) end - Rails.logger.debug("DEBUGGING: updated persisted workspaces with actual infos") - Rails.logger.debug("DEBUGGING: update_type: #{update_type}") if update_type == FULL # For a FULL update, return all workspaces for the agent which exist in the database @@ -43,7 +72,7 @@ def process(agent:, workspace_agent_infos:, update_type:) # For a PARTIAL update, return: # 1. Workspaces with_desired_state_updated_more_recently_than_last_response_to_agent # 2. Workspaces which we received from the agent in the agent_infos array - workspaces_from_agent_infos_ids = workspaces_from_agent_infos.map(&:id) + workspaces_from_agent_infos_ids = persisted_workspaces_from_agent_infos.map(&:id) workspaces_to_return_in_rails_infos_query = agent .workspaces @@ -59,8 +88,8 @@ def process(agent:, workspace_agent_infos:, update_type:) workspace_rails_info = { name: workspace.name, namespace: workspace.namespace, - actual_state: workspace.actual_state, desired_state: workspace.desired_state, + actual_state: workspace.actual_state, deployment_resource_version: workspace.deployment_resource_version, config_to_apply: config_to_apply(workspace: workspace, update_type: update_type) } @@ -74,12 +103,27 @@ def process(agent:, workspace_agent_infos:, update_type:) # noinspection RailsParamDefResolve workspaces_to_return_in_rails_infos_query.touch_all(:responded_to_agent_at) - Rails.logger.debug("DEBUGGING: workspace_rails_infos: #{workspace_rails_infos.inspect}") - payload = { workspace_rails_infos: workspace_rails_infos } + logger.debug( + message: 'Returning workspace_rails_infos', + agent_id: agent.id, + update_type: update_type, + count: workspace_rails_infos.length, + workspace_rails_infos: workspace_rails_infos.map do |rails_info| + { + name: rails_info.fetch(:name), + namespace: rails_info.fetch(:namespace), + desired_state: rails_info.fetch(:desired_state), + actual_state: rails_info.fetch(:actual_state), + deployment_resource_version: rails_info.fetch(:deployment_resource_version) + } + end + ) + [payload, nil] end + # rubocop:enable Metrics/AbcSize private @@ -99,44 +143,64 @@ def config_to_apply(workspace:, update_type:) desired_config_to_apply_array.join end - def check_for_orphan_workspaces(names_from_agent_infos, found_names) - orphan_workspaces = names_from_agent_infos - found_names - return unless orphan_workspaces.present? - - Rails.logger.error("DEBUGGING: ERROR: Received workspace agent info for workspaces " \ - "where no persisted workspace record exists: #{orphan_workspaces.inspect}") + def check_for_orphaned_workspaces( + workspace_agent_infos_by_name:, + persisted_workspace_names:, + agent_id:, + update_type: + ) + orphaned_workspace_agent_infos = workspace_agent_infos_by_name.reject do |name, _| + persisted_workspace_names.include?(name) + end.values + + return unless orphaned_workspace_agent_infos.present? + + logger.warn( + message: + 'Received orphaned workspace agent info for workspace(s) where no persisted workspace record exists', + error_type: 'orphaned_workspace', + agent_id: agent_id, + update_type: update_type, + count: orphaned_workspace_agent_infos.length, + orphaned_workspace_names: orphaned_workspace_agent_infos.map(&:name), + orphaned_workspace_namespaces: orphaned_workspace_agent_infos.map(&:namespace) + ) end - def update_existing_workspace_with_latest_info( - workspace:, + def update_persisted_workspace_with_latest_info( + persisted_workspace:, deployment_resource_version:, actual_state: ) # Handle the special case of RESTART_REQUESTED. desired_state is only set to 'RESTART_REQUESTED' until the # actual_state is detected as 'STOPPED', then we switch the desired_state to 'RUNNING' so it will restart. # See: https://gitlab.com/gitlab-org/remote-development/gitlab-remote-development-docs/blob/main/doc/architecture.md?plain=0#possible-desired_state-values - if workspace.desired_state == States::RESTART_REQUESTED && actual_state == States::STOPPED - workspace.desired_state = States::RUNNING + if persisted_workspace.desired_state == States::RESTART_REQUESTED && actual_state == States::STOPPED + persisted_workspace.desired_state = States::RUNNING end # Ensure workspaces are terminated after a max time-to-live. This is a temporary approach, we eventually want # to replace this with some mechanism to detect workspace activity and only shut down inactive workspaces. # Until then, this is the workaround to ensure workspaces don't live indefinitely. # See https://gitlab.com/gitlab-org/gitlab/-/issues/390597 - if workspace.created_at + workspace.max_hours_before_termination.hours < Time.current - workspace.desired_state = States::TERMINATED + if persisted_workspace.created_at + persisted_workspace.max_hours_before_termination.hours < Time.current + persisted_workspace.desired_state = States::TERMINATED end - workspace.actual_state = actual_state + persisted_workspace.actual_state = actual_state # In some cases a deployment resource version may not be present, e.g. if the initial creation request for the # workspace creation resulted in an Error. - workspace.deployment_resource_version = deployment_resource_version if deployment_resource_version + persisted_workspace.deployment_resource_version = deployment_resource_version if deployment_resource_version + + persisted_workspace.save! + end - workspace.save! + # TODO: Dry up memoized logger factory to a shared concern + def logger + @logger ||= RemoteDevelopment::Logger.build end end end end end -# rubocop:enable Gitlab/RailsLogger diff --git a/ee/spec/services/remote_development/workspaces/reconcile_service_spec.rb b/ee/spec/services/remote_development/workspaces/reconcile_service_spec.rb index 46d2e1bbbcb61b9569b986a0aabb2c3c0f18f7ea..2cc6a66774966fffd4d4daa0f1fee56c7c01760e 100644 --- a/ee/spec/services/remote_development/workspaces/reconcile_service_spec.rb +++ b/ee/spec/services/remote_development/workspaces/reconcile_service_spec.rb @@ -79,7 +79,7 @@ end expect(subject).to be_a(ServiceResponse) expect(subject.payload).to eq({}) # NOTE: A nil payload gets turned into an empty hash - expect(subject.message).to match(/unexpected error/) + expect(subject.message).to match(/Unexpected reconcile error/) expect(subject.reason).to eq(reason) end end