Adds structured logging for fines

* Adds a custom JSON formmater for production logs
* Adds adds more helpful logging data for diganosing fine problems
* Adds color logging for development
* Adds app_env and log_level Service keys

lib/routes/fines_and_fees.rb

@@ -11,24 +11,19 @@
   post "/pay" do
     fines = Fines.for(uniqname: session[:uniqname])
     total_sum = fines.total_sum.to_f
-    # 2024-06-06 This messages mrio when there's a fine to make it easier to determine if the fines bug is still happening.
-    begin
-      HTTParty.post(S.slack_url, headers: {"Content-type" => "application/json"}, body: {text: "Someone started a fine payment attempt in account"}.to_json)
-    rescue
-      S.logger.error("Couldn't send slack message")
-    end
 
     amount = (params["pay_in_full"] == "true") ? total_sum : params["partial_amount"].to_f
     if amount <= total_sum
       nelnet = Nelnet.new(amount_due: amount.to_currency)
       session["order_number"] = nelnet.order_number
-      S.logger.info("Fee payment attempt: order_number: #{nelnet.order_number}")
+      S.logger.info("fine_payment_start", message: "Fine payment started", order_number: nelnet.order_number)
       redirect nelnet.url
     else
       flash[:error] = "You don't need to overpay!!!"
       redirect "/fines-and-fees"
     end
-  rescue
+  rescue => e
+    S.logger.error("fine_payment_error", message: "Unable to redirect to payment website: #{e.detailed_message}")
     flash[:error] = "<span class='strong'>Error:</span> We were unable to redirect you to the payment website. Please try again"
     redirect "/fines-and-fees"
   end

lib/services.rb

@@ -21,4 +21,35 @@
   ENV["APP_VERSION"] || "APP_VERSION"
 end
 
-SemanticLogger.add_appender(io: S.log_stream, level: :info) unless ENV["APP_ENV"] == "test"
+S.register(:log_level) do
+  ENV["DEBUG"] ? :debug : :info
+end
+
+S.register(:app_env) do
+  ENV["APP_ENV"] || "development"
+end
+
+class ProductionFormatter < SemanticLogger::Formatters::Json
+  # Leave out the pid
+  def pid
+  end
+
+  # Leave out the timestamp
+  def time
+  end
+
+  # Leave out environment
+  def environment
+  end
+
+  # Leave out application (This would be Semantic Logger, which isn't helpful)
+  def application
+  end
+end
+
+case S.app_env
+when "production"
+  SemanticLogger.add_appender(io: S.log_stream, level: S.log_level, formatter: ProductionFormatter.new)
+when "development"
+  SemanticLogger.add_appender(io: S.log_stream, level: S.log_level, formatter: :color)
+end

models/fines/nelnet.rb

@@ -9,7 +9,6 @@ def initialize(amount_due:,
     order_type: "UMLibraryCirc",
     timestamp: DateTime.timestamp,
     order_number: "#{SecureRandom.alphanumeric(4)}.#{timestamp}")
-
     @payment_url = ENV.fetch("NELNET_PAYMENT_URL")
     @amount_due = amount_due.delete(".")
     @order_number = order_number

models/fines/receipt.rb

@@ -11,32 +11,37 @@ def initialize(payment:, balance:)
 
   def self.for(uniqname:, nelnet_params:, order_number:, is_valid: Nelnet.verify(nelnet_params))
     payment = Payment.new(nelnet_params)
+    error_params = {
+      order_number: order_number,
+      nelent_params: nelnet_params
+    }
     if !is_valid
-      S.logger.error("Fine payment error: order number #{order_number} payment could not be validated.")
+      S.logger.error("fine_payment_error", message: "order number #{order_number} payment could not be validated.", **error_params)
       return ErrorReceipt.new("Your payment could not be validated. Your payment order number is: #{payment.order_number}")
     end
-    if !/Approved/.match?(nelnet_params["transactionResultMessage"])
+    if !/approved/i.match?(nelnet_params["transactionResultMessage"])
+      S.logger.error("fine_payment_error", message: "transaction message is not \"Approved\"", **error_params)
       return ErrorReceipt.new("There was an error processing your payment.<br/>The error message is: #{nelnet_params["transactionResultMessage"]}<br/>Your payment order number is: #{order_number}")
     end
 
     payment_verification = Fines.verify_payment(uniqname: uniqname, order_number: order_number)
     if payment_verification.instance_of?(AlmaError)
-      S.logger.error("Fine payment error: order_number: #{payment.order_number}; message: #{payment_verification.message}")
+      S.logger.error("fine_payment_error", message: "There was an Alma error: #{payment_verification.message}", **error_params)
       ErrorReceipt.new("There was an error in processing your payment.<br>Your payment order number is: #{payment.order_number}<br>Server error: #{payment_verification.message}</br>")
     elsif payment_verification[:has_order_number]
-      S.logger.error("Fine payment error: order number #{order_number} is already in Alma.")
+      S.logger.error("fine_payment_error", message: "order number is already in Alma.", **error_params)
       ErrorReceipt.new("Your payment order number, #{order_number}, is already in the fines database.")
     elsif payment_verification[:total_sum].to_f.to_s == "0.0"
-      S.logger.error("Fine payment error: order number #{order_number} tried to pay $0.00")
+      S.logger.error("fine_payment_error", message: "Tried to pay $0.00", **error_params)
       ErrorReceipt.new("You do not have a balance. Your payment order number is: #{order_number}.")
     else # has not already paid
       resp = Fines.pay(uniqname: uniqname, amount: payment.amount, order_number: order_number)
       if resp.code != 200
         error = AlmaError.new(resp)
-        S.logger.error("Fine payment error: order number #{order_number}; message: #{error.message}")
+        S.logger.error("fine_payment_error", message: "Failed to apply payment to Alma: #{error.message}", **error_params)
         ErrorReceipt.new("#{error.message}<br>Your payment order number is: #{order_number}")
       else
-        S.logger.info("Fine payment success")
+        S.logger.info("fine_payment_success", message: "Fine payment success", order_number: order_number)
         Receipt.new(payment: payment, balance: resp.parsed_response["total_sum"])
       end
     end