diff --git a/app/controllers/customers_controller.rb b/app/controllers/customers_controller.rb index 8b2cab5..d74aa81 100644 --- a/app/controllers/customers_controller.rb +++ b/app/controllers/customers_controller.rb @@ -225,4 +225,8 @@ class CustomersController < ApplicationController return string end + def log(msg) + Rails.logger.info "[CustomersController] #{msg}" + end + end diff --git a/app/controllers/estimate_controller.rb b/app/controllers/estimate_controller.rb index 1cae0a4..429b5c2 100644 --- a/app/controllers/estimate_controller.rb +++ b/app/controllers/estimate_controller.rb @@ -25,7 +25,7 @@ class EstimateController < ApplicationController Estimate.sync_by_doc_number(params[:search]) e = Estimate.find_by_doc_number(params[:search]) rescue - logger.info "Estimate.find_by_doc_number failed" + log "Estimate.find_by_doc_number failed" end end @@ -35,7 +35,7 @@ class EstimateController < ApplicationController Estimate.sync_by_id(params[:id]) e = Estimate.find_by_id(params[:id]) rescue - logger.info "Estimate.find_by_id failed" + log "Estimate.find_by_id failed" end end @@ -68,4 +68,10 @@ class EstimateController < ApplicationController end end + private + + def log(msg) + Rails.logger.info "[EstimateController] #{msg}" + end + end diff --git a/app/jobs/bill_issue_time_job.rb b/app/jobs/bill_issue_time_job.rb index 76b2f09..c3e3eee 100644 --- a/app/jobs/bill_issue_time_job.rb +++ b/app/jobs/bill_issue_time_job.rb @@ -11,10 +11,11 @@ class BillIssueTimeJob < ActiveJob::Base queue_as :default + # Perform billing of unbilled time entries for a given issue by creating corresponding TimeActivity records in QuickBooks Online, and then marking those entries as billed in Redmine. This job is typically triggered after an invoice is created or updated to ensure all relevant time is captured for billing. def perform(issue_id) issue = Issue.find(issue_id) - Rails.logger.debug "QBO: Starting billing for issue ##{issue.id}" + log "Starting billing for issue ##{issue.id}" issue.with_lock do unbilled_entries = issue.time_entries.where(billed: [false, nil]).lock @@ -23,6 +24,7 @@ class BillIssueTimeJob < ActiveJob::Base totals = aggregate_hours(unbilled_entries) return if totals.blank? + log "Aggregated hours for billing: #{totals.inspect}" qbo = Qbo.first raise "No QBO configuration found" unless qbo @@ -35,14 +37,16 @@ class BillIssueTimeJob < ActiveJob::Base unbilled_entries.update_all(billed: true) end - Rails.logger.debug "QBO: Completed billing for issue ##{issue.id}" + log "Completed billing for issue ##{issue.id}" + Qbo.update_time_stamp rescue => e - Rails.logger.error "QBO: Billing failed for issue ##{issue_id} - #{e.message}" + log "Billing failed for issue ##{issue_id} - #{e.message}" raise e end private + # Aggregate time entries by activity name and sum their hours def aggregate_hours(entries) entries.includes(:activity) .group_by { |e| e.activity&.name } @@ -50,7 +54,9 @@ class BillIssueTimeJob < ActiveJob::Base .compact end + # Create TimeActivity records in QBO for each activity type with the appropriate hours and link them to the issue's assigned employee and customer def create_time_activities(issue, totals, access_token, qbo) + log "Creating TimeActivity records in QBO for issue ##{issue.id}" time_service = Quickbooks::Service::TimeActivity.new( company_id: qbo.realm_id, access_token: access_token @@ -82,12 +88,13 @@ class BillIssueTimeJob < ActiveJob::Base time_entry.hourly_rate = item.unit_price time_entry.item_id = item.id - Rails.logger.debug "QBO: Creating TimeActivity for #{activity_name} (#{hours}h #{minutes}m)" + log "Creating TimeActivity for #{activity_name} (#{hours}h #{minutes}m)" time_service.create(time_entry) end end + # Convert a decimal hours float into separate hours and minutes components for QBO TimeActivity def convert_hours(hours_float) total_minutes = (hours_float.to_f * 60).round hours = total_minutes / 60 @@ -95,14 +102,20 @@ class BillIssueTimeJob < ActiveJob::Base [hours, minutes] end + # Build a descriptive string for the TimeActivity based on the issue's tracker, ID, subject, and completion status def build_description(issue) base = "#{issue.tracker} ##{issue.id}: #{issue.subject}" return base if issue.closed? "#{base} (Partial @ #{issue.done_ratio}%)" end + # Find an item in QBO by name, escaping single quotes to prevent query issues. Returns nil if not found. def find_item(item_service, name) safe = name.gsub("'", "\\\\'") item_service.query("SELECT * FROM Item WHERE Name = '#{safe}'").first end + + def log(msg) + Rails.logger.info "[BillIssueTimeJob] #{msg}" + end end \ No newline at end of file diff --git a/app/jobs/estimate_sync_job.rb b/app/jobs/estimate_sync_job.rb index 4bad24b..3079da1 100644 --- a/app/jobs/estimate_sync_job.rb +++ b/app/jobs/estimate_sync_job.rb @@ -12,11 +12,12 @@ class EstimateSyncJob < ApplicationJob queue_as :default retry_on StandardError, wait: 5.minutes, attempts: 5 + # Sync estimates from QuickBooks Online to local database def perform(full_sync: false) qbo = Qbo.first return unless qbo - logger.info "[EstimateSyncJob] Starting #{full_sync ? 'full' : 'incremental'} sync..." + log "Starting #{full_sync ? 'full' : 'incremental'} sync..." qbo = Qbo.first qbo.perform_authenticated_request do |access_token| @@ -36,11 +37,12 @@ class EstimateSyncJob < ApplicationJob break if entries.size < 1000 end - logger.info "[EstimateSyncJob] Completed sync." + log "Completed sync." + Qbo.update_time_stamp end rescue => e - logger.error "[EstimateSyncJob] Fatal error: #{e.message}" - logger.error e.backtrace.join("\n") + log "Fatal error: #{e.message}" + log e.backtrace.join("\n") raise # allows retry end @@ -62,13 +64,13 @@ class EstimateSyncJob < ApplicationJob SQL end rescue => e - logger.error "[EstimateSyncJob] Failed to fetch page #{page}: #{e.message}" + log "Failed to fetch page #{page}: #{e.message}" nil end # Sync a single estimate record def sync_estimates(e) - logger.info "[EstimateSyncJob] Processing estimate #{e.id} doc=#{e.doc_number} status=#{e.txn_status}" + log "Processing estimate #{e.id} doc=#{e.doc_number} status=#{e.txn_status}" estimate = Estimate.find_or_initialize_by(id: e.id) @@ -78,13 +80,17 @@ class EstimateSyncJob < ApplicationJob if estimate.changed? estimate.save - logger.info "[EstimateSyncJob] Updated estimate #{e.id}" + log "Updated estimate #{e.id}" end end # TODO remove deleted estimates rescue => error - logger.error "[EstimateSyncJob] Failed to sync estimate #{e.id}: #{error.message}" + log "Failed to sync estimate #{e.id}: #{error.message}" + end + + def log(msg) + Rails.logger.info "[EstimateSyncJob] #{msg}" end end \ No newline at end of file diff --git a/app/jobs/webhook_process_job.rb b/app/jobs/webhook_process_job.rb index eb398d1..6fa3058 100644 --- a/app/jobs/webhook_process_job.rb +++ b/app/jobs/webhook_process_job.rb @@ -17,7 +17,9 @@ class WebhookProcessJob < ActiveJob::Base Estimate ].freeze + # Process incoming QBO webhook notifications and sync relevant data to Redmine def perform(raw_body) + log "Received webhook: #{raw_body}" data = JSON.parse(raw_body) data.fetch('eventNotifications', []).each do |notification| @@ -33,7 +35,9 @@ class WebhookProcessJob < ActiveJob::Base private + # Process a single entity from the webhook payload and sync it to Redmine if it's an allowed type def process_entity(entity) + log "Processing entity: #{entity}" name = entity['name'] id = entity['id']&.to_i @@ -53,7 +57,10 @@ class WebhookProcessJob < ActiveJob::Base model.sync_by_id(id) end rescue => e - Rails.logger.error "QBO Webhook entity processing failed" - Rails.logger.error e.message + log "#{e.message}" + end + + def log(msg) + Rails.logger.info "[WebhookProcessJob] #{msg}" end end \ No newline at end of file diff --git a/app/models/concerns/quickbooks_oauth.rb b/app/models/concerns/quickbooks_oauth.rb index 0a0138c..c7f6f2d 100644 --- a/app/models/concerns/quickbooks_oauth.rb +++ b/app/models/concerns/quickbooks_oauth.rb @@ -13,12 +13,13 @@ module QuickbooksOauth #== Instance Methods + # This method will attempt to execute the block and if it encounters an OAuth2::Error or Quickbooks::AuthorizationFailure it will attempt to refresh the token and retry the block. It will try this up to 3 times before giving up and raising an exception. def perform_authenticated_request(&block) attempts = 0 begin yield oauth_access_token rescue OAuth2::Error, Quickbooks::AuthorizationFailure => ex - Rails.logger.error("QuickbooksOauth.perform: #{ex.message}") + log "perform_authenticated_request: #{ex.message}" # to prevent an infinite loop here keep a counter and bail out after N times... attempts += 1 @@ -32,8 +33,9 @@ module QuickbooksOauth end end + # This method will attempt to refresh the access token and update the record with the new access token, refresh token and their respective expiration times. If the refresh token expires in more than 0 seconds then we will set the refresh token expiration time to that value, otherwise we will set it to 100 days from now. def refresh_token! - Rails.logger.info("QuickbooksOauth.refresh_token!") + log "refresh_token!" t = oauth_access_token refreshed = t.refresh! @@ -43,7 +45,7 @@ module QuickbooksOauth oauth2_refresh_token_expires_at = 100.days.from_now end - Rails.logger.info("QuickbooksOauth.refresh_token!: #{oauth2_refresh_token_expires_at}") + log "refresh_token!: #{oauth2_refresh_token_expires_at}" update!( oauth2_access_token: refreshed.token, @@ -53,20 +55,24 @@ module QuickbooksOauth ) end + # This method will return an instance of the OAuth2::Client class that is configured with the consumer key, consumer secret and the appropriate URLs for the Intuit OAuth2 service. It will also set the sandbox mode based on the plugin settings. def oauth_client self.class.construct_oauth2_client end + # This method will return an instance of the OAuth2::AccessToken class that is configured with the current access token, refresh token and the OAuth2 client. This access token can be used to make authenticated requests to the Intuit API. def oauth_access_token OAuth2::AccessToken.new(oauth_client, oauth2_access_token, refresh_token: oauth2_refresh_token) end + # This method is an alias for the oauth_access_token method and is used to provide a more intuitive name for the access token when making authenticated requests. def consumer oauth_access_token end module ClassMethods + # This method will construct and return an instance of the OAuth2::Client class that is configured with the consumer key, consumer secret and the appropriate URLs for the Intuit OAuth2 service. It will also set the sandbox mode based on the plugin settings. This method is used by the instance method oauth_client to create a new OAuth2 client for each instance of the model that includes this concern. def construct_oauth2_client oauth_consumer_key = Setting.plugin_redmine_qbo['settingsOAuthConsumerKey'] @@ -74,7 +80,7 @@ module QuickbooksOauth # Are we are playing in the sandbox? Quickbooks.sandbox_mode = Setting.plugin_redmine_qbo[:sandbox] ? true : false - logger.info "Sandbox mode: #{Quickbooks.sandbox_mode}" + log "Sandbox mode: #{Quickbooks.sandbox_mode}" options = { site: "https://appcenter.intuit.com/connect/oauth2", @@ -85,4 +91,11 @@ module QuickbooksOauth end end + + + private + + def log(msg) + Rails.logger.info "[QuickbooksOauth] #{msg}" + end end diff --git a/app/models/estimate.rb b/app/models/estimate.rb index d469eae..6782915 100644 --- a/app/models/estimate.rb +++ b/app/models/estimate.rb @@ -27,7 +27,7 @@ class Estimate < ActiveRecord::Base # sync only one estimate def self.sync_by_id(id) - logger.info "Syncing estimate #{id}" + log "Syncing estimate #{id}" qbo = Qbo.first qbo.perform_authenticated_request do |access_token| service = Quickbooks::Service::Estimate.new(company_id: qbo.realm_id, access_token: access_token) @@ -37,7 +37,7 @@ class Estimate < ActiveRecord::Base # sync only one estimate def self.sync_by_doc_number(number) - logger.info "Syncing estimate by doc number #{number}" + log "Syncing estimate by doc number #{number}" qbo = Qbo.first qbo.perform_authenticated_request do |access_token| service = Quickbooks::Service::Estimate.new(company_id: qbo.realm_id, access_token: access_token) @@ -63,7 +63,7 @@ class Estimate < ActiveRecord::Base # process an estimate into the database def self.process_estimate(qbo_estimate) - logger.info "Processing estimate #{qbo_estimate.id}" + log "Processing estimate #{qbo_estimate.id}" estimate = find_or_create_by(id: qbo_estimate.id) estimate.doc_number = qbo_estimate.doc_number estimate.customer_id = qbo_estimate.customer_ref.value @@ -115,5 +115,9 @@ class Estimate < ActiveRecord::Base @details = Quickbooks::Model::Estimate.new end end + + def log(msg) + Rails.logger.info "[Estimate] #{msg}" + end end diff --git a/app/models/qbo.rb b/app/models/qbo.rb index 82c371e..ca830b2 100644 --- a/app/models/qbo.rb +++ b/app/models/qbo.rb @@ -16,7 +16,7 @@ class Qbo < ActiveRecord::Base # Updates last sync time stamp def self.update_time_stamp date = DateTime.now - logger.info "Updating QBO timestamp to #{date}" + log "Updating QBO timestamp to #{date}" qbo = Qbo.first qbo.last_sync = date qbo.save @@ -25,4 +25,11 @@ class Qbo < ActiveRecord::Base def self.last_sync format_time(Qbo.first.last_sync) end + + private + + def self.log(msg) + logger.info "[QBO] #{msg}" + end + end diff --git a/lib/redmine_qbo/hooks/issues_hook_listener.rb b/lib/redmine_qbo/hooks/issues_hook_listener.rb index 65308e9..0b56dec 100644 --- a/lib/redmine_qbo/hooks/issues_hook_listener.rb +++ b/lib/redmine_qbo/hooks/issues_hook_listener.rb @@ -17,12 +17,12 @@ module RedmineQbo # Edit Issue Form # Here we build the required form components before passing them to a partial view formatting. def view_issues_form_details_bottom(context={}) - Rails.logger.debug "RedmineQbo::Hooks::IssuesHookListener.view_issues_form_details_bottom: Building form components for quickbooks customer, estimate, and invoice data" + log "view_issues_form_details_bottom: Building form components for quickbooks customer, estimate, and invoice data" f = context[:form] issue = context[:issue] project = context[:project] - Rails.logger.debug issue.inspect - Rails.logger.debug project.inspect + log issue.inspect + log project.inspect # Customer Name Text Box with database backed autocomplete # onchange event will update the hidden customer_id field @@ -44,7 +44,7 @@ module RedmineQbo # # If this is not handled correctly, it leads to a 422 error when creating a new issue and selecting a customer. js_path = "updateIssueFrom('#{escape_javascript update_issue_form_path(project, issue)}', this)" - Rails.logger.debug js_path + log js_path # This hidden field is used for the customer ID for the issue # the onchange event will reload the issue form via ajax to update the available estimates @@ -93,6 +93,12 @@ module RedmineQbo } }) end + + private + + def log(msg) + Rails.logger.info "[IssuesHookListener] #{msg}" + end end end diff --git a/lib/redmine_qbo/patches/issue_patch.rb b/lib/redmine_qbo/patches/issue_patch.rb index 1f23d48..590a697 100644 --- a/lib/redmine_qbo/patches/issue_patch.rb +++ b/lib/redmine_qbo/patches/issue_patch.rb @@ -27,6 +27,7 @@ module RedmineQbo before_save :titlize_subject after_commit :enqueue_billing, on: :update end + end module ClassMethods @@ -35,20 +36,22 @@ module RedmineQbo module InstanceMethods + # Enqueue a background job to bill the time spent on this issue to the associated customer in Quickbooks, if the issue is closed and has a customer assigned. def enqueue_billing - Rails.logger.debug "QBO: Checking if issue needs to be billed for issue ##{id}" + log "Checking if issue needs to be billed for issue ##{id}" #return unless saved_change_to_status_id? return unless closed? return unless customer.present? return unless assigned_to&.employee_id.present? return unless Qbo.first - Rails.logger.debug "QBO: Enqueuing billing for issue ##{id}" + log "Enqueuing billing for issue ##{id}" BillIssueTimeJob.perform_later(id) end + # Titlize the subject of the issue before saving to ensure consistent formatting for billing descriptions in Quickbooks def titlize_subject - Rails.logger.debug "QBO: Titlizing subject for issue ##{id}" + log "Titlizing subject for issue ##{id}" self.subject = subject.split(/\s+/).map do |word| if word =~ /[A-Z]/ && word =~ /[0-9]/ @@ -60,9 +63,16 @@ module RedmineQbo end end + # This method is used to generate a shareable token for the customer associated with this issue, which can be used to link the issue to the corresponding customer in Quickbooks for billing and tracking purposes. def share_token CustomerToken.get_token(self) end + + private + + def log(msg) + Rails.logger.info "[IssuePatch] #{msg}" + end end Issue.send(:include, IssuePatch)