Extend logs and raise the D-Bus timeout

rust/share/dbus-test.conf

@@ -65,7 +65,7 @@
   <limit name="max_message_size">1000000000</limit>
   <!-- We do not override max_message_unix_fds here since the in-kernel
        limit is also relatively low -->
-  <limit name="service_start_timeout">120000</limit>  
+  <limit name="service_start_timeout">600000</limit>
   <limit name="auth_timeout">240000</limit>
   <limit name="pending_fd_timeout">150000</limit>
   <limit name="max_completed_connections">100000</limit>  

service/bin/agamactl

@@ -43,7 +43,7 @@ def logger_for(name)
     formatter = Logger::Formatter.new # the default
   else
     # going via syslog which will provide time and progname already
-    formatter = ->(severity, _time, _progname, msg) { "#{severity}: #{msg}\n" }
+    formatter = ->(severity, _time, _progname, msg) { "[#{severity}]: #{name}: #{msg}\n" }
     $stdout.sync = true
   end
 
@@ -59,7 +59,9 @@ def start_service(name)
   module_y2dir = File.expand_path("../lib/agama/dbus/y2dir/#{name}", __dir__)
   ENV["Y2DIR"] = [ENV.fetch("Y2DIR", nil), module_y2dir, general_y2dir].compact.join(":")
 
-  service_runner = Agama::DBus::ServiceRunner.new(name, logger: logger_for(name))
+  logger = logger_for(name)
+  service_runner = Agama::DBus::ServiceRunner.new(name, logger: logger)
+  logger.info "Starting the service"
   service_runner.run
 end
 

service/lib/agama/manager.rb

@@ -64,6 +64,7 @@ def initialize(config, logger)
       @installation_phase = InstallationPhase.new
       @service_status_recorder = ServiceStatusRecorder.new
       @service_status = DBus::ServiceStatus.new.busy
+      on_progress_change { logger.info progress.to_s }
     end
 
     # Runs the startup phase

service/lib/agama/progress.rb

@@ -145,5 +145,14 @@ def on_change(&block)
     def on_finish(&block)
       @on_finish_callbacks << block
     end
+
+    # Returns a string-based representation of the progress
+    #
+    # @return [String]
+    def to_s
+      return "Finished" if finished?
+
+      "#{current_step.description} (#{@counter}/#{total_steps})"
+    end
   end
 end

service/lib/agama/software/manager.rb

@@ -73,6 +73,7 @@ def initialize(config, logger)
           @config.pick_product(@product)
         end
         @repositories = RepositoriesManager.new
+        on_progress_change { logger.info progress.to_s }
       end
 
       def select_product(name)

service/lib/agama/storage/manager.rb

@@ -52,6 +52,7 @@ def initialize(config, logger)
         @config = config
         @logger = logger
         register_proposal_callbacks
+        on_progress_change { logger.info progress.to_s }
       end
 
       # Whether the system is in a deprecated status

service/package/rubygem-agama.changes

@@ -1,3 +1,11 @@
+-------------------------------------------------------------------
+Fri Sep  1 07:32:59 UTC 2023 - Imobach Gonzalez Sosa <igonzalezsosa@suse.com>
+
+- Extend the Ruby-based services logs with information about
+  each step (gh#openSUSE/agama#732).
+- Raise the D-Bus service start timeout for troubleshoting purposes
+  (related to bsc#1214737).
+
 -------------------------------------------------------------------
 Thu Aug 31 10:36:53 UTC 2023 - Imobach Gonzalez Sosa <igonzalezsosa@suse.com>
 

service/share/dbus.conf

@@ -67,7 +67,7 @@
   <limit name="max_message_size">1000000000</limit>
   <!-- We do not override max_message_unix_fds here since the in-kernel
        limit is also relatively low -->
-  <limit name="service_start_timeout">120000</limit>  
+  <limit name="service_start_timeout">600000</limit>
   <limit name="auth_timeout">240000</limit>
   <limit name="pending_fd_timeout">150000</limit>
   <limit name="max_completed_connections">100000</limit>  

service/test/agama/progress_test.rb

@@ -227,4 +227,22 @@
       end
     end
   end
+
+  describe "#to_s" do
+    let(:steps) { 2 }
+
+    before { subject.step("Probing software") }
+
+    it "returns the step description an the current/total steps" do
+      expect(subject.to_s).to eq("Probing software (1/2)")
+    end
+
+    context "when the progress is finished" do
+      before { subject.step("Probing storage") }
+
+      it "returns 'Finished' when the progress is finished" do
+        expect(subject.to_s).to eq("Finished")
+      end
+    end
+  end
 end