Troubleshoot hanging rspec runs that caused job time outs

.github/workflows/ci.yml

@@ -163,14 +163,40 @@ jobs:
           key: openHAB-setup-2-${{ matrix.openhab_version }}${{ endsWith(matrix.openhab_version, 'SNAPSHOT') && needs.openhab-snapshot-date.outputs.date || '' }}-java-${{ matrix.java_version }}
           fail-on-cache-miss: true
       - name: RSpec
-        run: bin/rspec --format progress --format html --out rspec.html
+        run: |
+          set -euo pipefail
+          bin/rspec --format progress --format html --out rspec.html &
+          rspec_pid=$!
+          start_time=$(date +%s)
+
+          while kill -0 "$rspec_pid" 2>/dev/null; do
+            sleep 30
+            now=$(date +%s)
+            elapsed=$((now - start_time))
+            echo "[heartbeat] $(date -u +%FT%TZ) rspec still running (${elapsed}s elapsed)"
+
+            if [[ "$elapsed" -ge 330 ]]; then
+              echo "RSpec exceeded 330s; collecting thread dump before termination"
+              kill -QUIT "$rspec_pid" || true
+              sleep 5
+              kill -TERM "$rspec_pid" || true
+              sleep 20
+              kill -KILL "$rspec_pid" || true
+              wait "$rspec_pid" || true
+              exit 124
+            fi
+          done
+
+          wait "$rspec_pid"
         timeout-minutes: 6
       - name: Upload openHAB Logs
         uses: actions/upload-artifact@v6
         if: failure()
         with:
           name: RSpec-logs-${{ matrix.openhab_version }}-${{ matrix.jruby_version }}-java-${{ matrix.java_version }}
-          path: tmp/openhab/userdata/logs
+          path: |
+            tmp/openhab/userdata/logs
+            tmp/karaf.log
           retention-days: 2
       - name: Upload RSpec results
         uses: actions/upload-artifact@v6

lib/openhab/rspec/helpers.rb

@@ -364,19 +364,35 @@ def load_transforms
       # @param [String] addon_id The addon id, such as "binding-mqtt"
       # @param [true,false] wait Wait until OSGi has confirmed the bundle is installed and running before returning.
       # @param [String,Array<String>] ready_markers Array of ready marker types to wait for.
+      # @param [Numeric] install_timeout Max seconds to wait for addon installation.
+      # @param [Numeric] ready_timeout Max seconds to wait for ready markers.
       #   The addon's bundle id is used as the identifier.
       # @return [void]
       #
-      def install_addon(addon_id, wait: true, ready_markers: nil)
+      def install_addon(addon_id, wait: true, ready_markers: nil, install_timeout: 30, ready_timeout: 30)
         service_filter = "(component.name=org.openhab.core.karafaddons)"
         addon_service = OSGi.service("org.openhab.core.addon.AddonService", filter: service_filter)
         addon_service.install(addon_id)
         return unless wait
 
         addon = nil
+        install_start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
+        install_deadline = install_start + install_timeout
+        next_install_log_at = install_start + 5
         loop do
           addon = addon_service.get_addon(addon_id, nil)
-          break if addon.installed?
+          break if addon&.installed?
+
+          now = Process.clock_gettime(Process::CLOCK_MONOTONIC)
+          if now >= next_install_log_at
+            elapsed = (now - install_start).round(1)
+            logger.warn("Still waiting for addon to install: #{addon_id} (elapsed=#{elapsed}s, timeout=#{install_timeout}s)") # rubocop:disable Layout/LineLength
+            next_install_log_at = now + 5
+          end
+
+          if now >= install_deadline
+            raise "Timed out after #{install_timeout}s waiting for addon installation: #{addon_id}"
+          end
 
           sleep 0.25
         end
@@ -395,8 +411,29 @@ def install_addon(addon_id, wait: true, ready_markers: nil)
         end
 
         rs = OSGi.service("org.openhab.core.service.ReadyService")
+        start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
+        deadline = start + ready_timeout
+        next_log_at = start + 5
+
         loop do
-          break if ready_markers.all? { |rm| rs.ready?(rm) }
+          now = Process.clock_gettime(Process::CLOCK_MONOTONIC)
+          pending_markers = ready_markers.reject { |rm| rs.ready?(rm) }
+          break if pending_markers.empty?
+
+          pending_marker_text = pending_markers
+                                .map { |rm| "#{rm.type}(#{rm.identifier})" }
+                                .join(", ")
+
+          if now >= next_log_at
+            elapsed = (now - start).round(1)
+            logger.warn("Still waiting for ready markers for #{addon_id} (elapsed=#{elapsed}s, timeout=#{ready_timeout}s): #{pending_marker_text}") # rubocop:disable Layout/LineLength
+            next_log_at = now + 5
+          end
+
+          if now >= deadline
+            logger.warn("Timed out waiting for ready markers for #{addon_id}: #{pending_marker_text}")
+            raise "Timed out after #{ready_timeout}s waiting for ready markers for #{addon_id}: #{pending_marker_text}"
+          end
 
           sleep 0.25
         end

lib/openhab/rspec/karaf.rb

@@ -382,7 +382,7 @@ def set_up_bundle_listener
           @thing_type_tracker.class.field_reader :openState
           org.openhab.core.config.core.xml.osgi.XmlDocumentBundleTracker::OpenState.field_reader :OPENED
           opened = org.openhab.core.config.core.xml.osgi.XmlDocumentBundleTracker::OpenState.OPENED
-          sleep until @thing_type_tracker.openState == opened
+          wait_until("thing type tracker open") { @thing_type_tracker.openState == opened }
           @bundle_context.bundles.each do |bundle|
             @thing_type_tracker.adding_bundle(bundle, nil)
           end
@@ -394,7 +394,7 @@ def set_up_bundle_listener
           @config_description_tracker.class.field_reader :openState
           org.openhab.core.config.core.xml.osgi.XmlDocumentBundleTracker::OpenState.field_reader :OPENED
           opened = org.openhab.core.config.core.xml.osgi.XmlDocumentBundleTracker::OpenState.OPENED
-          sleep until @config_description_tracker.openState == opened
+          wait_until("config description tracker open") { @config_description_tracker.openState == opened }
           @bundle_context.bundles.each do |bundle|
             @config_description_tracker.adding_bundle(bundle, nil)
           end
@@ -532,7 +532,7 @@ def wait_for_service(service_name, filter: nil, &block)
       end
 
       def wait_for_start
-        wait do |continue|
+        wait(timeout: 120, label: "all bundles to start") do |continue|
           @all_bundles_continue = continue
           next continue.call if all_bundles_started?
         end
@@ -557,10 +557,11 @@ def blocked_bundle?(bundle)
           bundle.fragment?
       end
 
-      def wait(timeout: 30)
+      def wait(timeout: 30, label: nil)
         mutex = Mutex.new
         cond = ConditionVariable.new
         skip_wait = false
+        timed_out = false
 
         continue = lambda do
           # if continue was called synchronously, we can just return
@@ -570,8 +571,40 @@ def wait(timeout: 30)
         end
         mutex.synchronize do
           yield continue
-          cond.wait(mutex, timeout) unless skip_wait
+          timed_out = !cond.wait(mutex, timeout) unless skip_wait
         end
+
+        return unless timed_out
+
+        detail = label ? " while waiting for #{label}" : ""
+        raise "Timed out after #{timeout}s#{detail}. #{bundle_state_summary}"
+      end
+
+      def wait_until(label, timeout: 30, interval: 0.1)
+        deadline = Process.clock_gettime(Process::CLOCK_MONOTONIC) + timeout
+        until yield
+          if Process.clock_gettime(Process::CLOCK_MONOTONIC) >= deadline
+            raise "Timed out after #{timeout}s while waiting for #{label}. #{bundle_state_summary}"
+          end
+
+          sleep interval
+        end
+      end
+
+      def bundle_state_summary
+        return "Bundle state unavailable" unless @bundle_context
+
+        bundle_counts = @bundle_context.bundles.each_with_object(Hash.new(0)) do |bundle, counts|
+          counts[bundle.state] += 1
+        end
+
+        active = org.osgi.framework.Bundle::ACTIVE
+        resolved = org.osgi.framework.Bundle::RESOLVED
+        starting = org.osgi.framework.Bundle::STARTING
+        installed = org.osgi.framework.Bundle::INSTALLED
+
+        "Bundles: active=#{bundle_counts[active]}, resolved=#{bundle_counts[resolved]}, " \
+          "starting=#{bundle_counts[starting]}, installed=#{bundle_counts[installed]}, total=#{@bundle_context.bundles.length}" # rubocop:disable Layout/LineLength
       end
 
       def link_osgi