Use proper logging, more errors from tasks should now trigger showing the error dialog instead of siliently failing

.gitignore

@@ -2,6 +2,8 @@ pkg/
 *.json
 data/cache/*
 !data/cache/.gitkeep
+data/logs/*
+!data/logs/.gitkeep
 _*.*
 *.log
 media/icons/*

lib/api.rb

@@ -1,5 +1,8 @@
 class W3DHub
   class Api
+    LOG_TAG = "W3DHub::Api".freeze
+
+    API_TIMEOUT = 10 # seconds
     USER_AGENT = "Cyberarm's Linux Friendly W3D Hub Launcher v#{W3DHub::VERSION}".freeze
     DEFAULT_HEADERS = [
       ["User-Agent", USER_AGENT],
@@ -13,6 +16,12 @@ class W3DHub
       BackgroundWorker.job(-> { Api.send(method, *args) }, callback)
     end
 
+    class DummyResponse
+      def success?
+        false
+      end
+    end
+
     #! === W3D Hub API === !#
 
     ENDPOINT = "https://secure.w3dhub.com".freeze
@@ -22,14 +31,28 @@ class W3DHub
 
       # TODO: Check if session has expired and attempt to refresh session before submitting request
 
+      logger.debug(LOG_TAG) { "Fetching POST \"#{url}\"..." }
+
       # Inject Authorization header if account data is populated
       if Store.account
+        logger.debug(LOG_TAG) { "  Injecting Authorization header..." }
         headers = headers.dup
         headers << ["Authorization", "Bearer #{Store.account.access_token}"]
       end
 
+      begin
+        Async::Task.current.with_timeout(API_TIMEOUT) do
           @client.post(url, headers, body)
         end
+      rescue Async::TimeoutError
+        logger.error(LOG_TAG) { "Connection to \"#{url}\" timed out after: #{API_TIMEOUT} seconds" }
+        DummyResponse.new
+      rescue EOFError
+        logger.error(LOG_TAG) { "Connection to \"#{url}\" errored:" }
+        logger.error(LOG_TAG) { e }
+        DummyResponse.new
+      end
+    end
 
     # Method: POST
     # FORMAT: JSON
@@ -50,7 +73,7 @@ class W3DHub
       body = "data=#{JSON.dump({refreshToken: refresh_token})}"
       response = post("#{ENDPOINT}/apis/launcher/1/user-login", FORM_ENCODED_HEADERS, body)
 
-      if response.success?#status == 200
+      if response.success?
         user_data = JSON.parse(response.read, symbolize_names: true)
 
         return false if user_data[:error]
@@ -60,10 +83,15 @@ class W3DHub
 
         if user_details.success?
           user_details_data = JSON.parse(user_details.read, symbolize_names: true)
+        else
+          logger.error(LOG_TAG) { "Failed to fetch refresh user details:" }
+          logger.error(LOG_TAG) { user_details }
         end
 
-        return Account.new(user_data, user_details_data)
+        Account.new(user_data, user_details_data)
       else
+        logger.error(LOG_TAG) { "Failed to fetch refresh user login:" }
+        logger.error(LOG_TAG) { response }
         false
       end
     end
@@ -83,10 +111,15 @@ class W3DHub
 
         if user_details.success?
           user_details_data = JSON.parse(user_details.read, symbolize_names: true)
+        else
+          logger.error(LOG_TAG) { "Failed to fetch user details:" }
+          logger.error(LOG_TAG) { user_details }
         end
 
-        return Account.new(user_data, user_details_data)
+        Account.new(user_data, user_details_data)
       else
+        logger.error(LOG_TAG) { "Failed to fetch user login:" }
+        logger.error(LOG_TAG) { response }
         false
       end
     end
@@ -107,6 +140,8 @@ class W3DHub
       if response.success?
         ServiceStatus.new(response.read)
       else
+        logger.error(LOG_TAG) { "Failed to fetch service status:" }
+        logger.error(LOG_TAG) { response }
         false
       end
     end
@@ -121,6 +156,8 @@ class W3DHub
       if response.success?
         Applications.new(response.read)
       else
+        logger.error(LOG_TAG) { "Failed to fetch applications list:" }
+        logger.error(LOG_TAG) { response }
         false
       end
     end
@@ -136,6 +173,9 @@ class W3DHub
       if response.success?
         News.new(response.read)
       else
+        logger.error(LOG_TAG) { "Failed to fetch news for:" }
+        logger.error(LOG_TAG) { category }
+        logger.error(LOG_TAG) { response }
         false
       end
     end
@@ -152,7 +192,9 @@ class W3DHub
         hash = JSON.parse(response.read, symbolize_names: true)
         hash[:packages].map { |pkg| Package.new(pkg) }
       else
-        pp response
+        logger.error(LOG_TAG) { "Failed to fetch package details for:" }
+        logger.error(LOG_TAG) { packages }
+        logger.error(LOG_TAG) { response }
         false
       end
     end
@@ -172,6 +214,8 @@ class W3DHub
     def self.get(url, headers = DEFAULT_HEADERS, body = nil)
       @client ||= Async::HTTP::Client.new(Async::HTTP::Endpoint.parse(SERVER_LIST_ENDPOINT, protocol: Async::HTTP::Protocol::HTTP10))
 
+      logger.debug(LOG_TAG) { "Fetching GET \"#{url}\"..." }
+
       @client.get(url, headers, body)
     end
 

lib/api/server_list_updater.rb

@@ -1,6 +1,7 @@
 class W3DHub
   class Api
     class ServerListUpdater
+      LOG_TAG = "W3DHub::Api::ServerListUpdater".freeze
       include CyberarmEngine::Common
 
       ##!!! When this breaks update from: https://github.com/socketry/async-websocket/blob/master/lib/async/websocket/connection.rb
@@ -70,6 +71,7 @@ class W3DHub
       end
 
       def initialize
+        logger.info(LOG_TAG) { "Starting emulated SignalR Server List Updater..." }
         run
       end
 
@@ -78,18 +80,23 @@ class W3DHub
           Async do |task|
             internet = Async::HTTP::Internet.instance
 
+            logger.debug(LOG_TAG) { "Requesting connection token..." }
             response = internet.post("https://gsh.w3dhub.com/listings/push/v2/negotiate?negotiateVersion=1", Api::DEFAULT_HEADERS, [""])
             data = JSON.parse(response.read, symbolize_names: true)
 
             id = data[:connectionToken]
             endpoint = Async::HTTP::Endpoint.parse("https://gsh.w3dhub.com/listings/push/v2?id=#{id}", alpn_protocols: Async::HTTP::Protocol::HTTP11.names)
 
+            logger.debug(LOG_TAG) { "Connecting to websocket..." }
             Async::WebSocket::Client.connect(endpoint, headers: Api::DEFAULT_HEADERS, handler: PatchedConnection) do |connection|
+              logger.debug(LOG_TAG) { "Requesting json protocol, v1..." }
               connection.write({ protocol: "json", version: 1 })
               connection.flush
-              pp connection.read
+              logger.debug(LOG_TAG) { "Received: #{connection.read}" }
+              logger.debug(LOG_TAG) { "Sending \"PING\"(?)" }
               connection.write({ "type": 6 })
 
+              logger.debug(LOG_TAG) { "Subscribing to server changes..." }
               Store.server_list.each_with_index do |server, i|
                 i += 1
                 mode = 1 # 2 full details, 1 basic details
@@ -97,7 +104,9 @@ class W3DHub
                 connection.write(out)
               end
 
+              logger.debug(LOG_TAG) { "Waiting for data..." }
               while (message = connection.read)
+                logger.debug(LOG_TAG) { "Sending \"PING\"(?)" } if message.first[:type] == 6
                 connection.write({ type: 6 }) if message.first[:type] == 6
 
                 if message&.first&.fetch(:type) == 1
@@ -108,11 +117,13 @@ class W3DHub
                     server = Store.server_list.find { |s| s.id == id }
                     server_updated = server&.update(data)
                     States::Interface.instance&.update_server_browser(server) if server_updated
+                    logger.debug(LOG_TAG) { "Updated #{server.status.name}" } if server_updated
                   end
                 end
               end
             end
           ensure
+            logger.debug(LOG_TAG) { "Cleaning up..." }
             @@instance = nil
           end
         end

lib/application_manager.rb

@@ -1,5 +1,6 @@
 class W3DHub
   class ApplicationManager
+    LOG_TAG = "W3DHub::ApplicationManager".freeze
     include CyberarmEngine::Common
 
     def initialize
@@ -7,7 +8,7 @@ class W3DHub
     end
 
     def install(app_id, channel)
-      puts "Installation Request: #{app_id}-#{channel}"
+      logger.info(LOG_TAG) { "Installation Request: #{app_id}-#{channel}" }
 
       return false if installed?(app_id, channel) || installing?(app_id, channel)
 
@@ -27,7 +28,7 @@ class W3DHub
     end
 
     def update(app_id, channel)
-      puts "Update Request: #{app_id}-#{channel}"
+      logger.info(LOG_TAG) { "Update Request: #{app_id}-#{channel}" }
 
       return false unless installed?(app_id, channel)
 
@@ -37,7 +38,7 @@ class W3DHub
     end
 
     def import(app_id, channel)
-      puts "Import Request: #{app_id}-#{channel}"
+      logger.info(LOG_TAG) { "Import Request: #{app_id}-#{channel}" }
 
       # Check registry for auto-import if windows
       # if auto-import fails ask user for path to game exe
@@ -47,7 +48,7 @@ class W3DHub
     end
 
     def settings(app_id, channel)
-      puts "Settings Request: #{app_id}-#{channel}"
+      logger.info(LOG_TAG) { "Settings Request: #{app_id}-#{channel}" }
 
       # open wwconfig.exe or config.exe for ecw
 
@@ -70,7 +71,7 @@ class W3DHub
     end
 
     def wine_configuration(app_id, channel)
-      puts "Wine Configuration Request: #{app_id}-#{channel}"
+      logger.info(LOG_TAG) { "Wine Configuration Request: #{app_id}-#{channel}" }
 
       # open wwconfig.exe or config.exe for ecw
 
@@ -86,7 +87,7 @@ class W3DHub
     end
 
     def repair(app_id, channel)
-      puts "Repair Installation Request: #{app_id}-#{channel}"
+      logger.info(LOG_TAG) { "Repair Installation Request: #{app_id}-#{channel}" }
 
       return false if !installed?(app_id, channel) || installing?(app_id, channel)
 
@@ -101,7 +102,7 @@ class W3DHub
     end
 
     def uninstall(app_id, channel)
-      puts "Uninstall Request: #{app_id}-#{channel}"
+      logger.info(LOG_TAG) { "Uninstall Request: #{app_id}-#{channel}" }
 
       return false if !installed?(app_id, channel) || installing?(app_id, channel)
 
@@ -118,7 +119,7 @@ class W3DHub
     end
 
     def show_folder(app_id, channel, type)
-      puts "Show Folder Request: #{app_id} -> #{type.inspect}"
+      logger.info(LOG_TAG) { "Show Folder Request: #{app_id} -> #{type.inspect}" }
 
       app_data = installed?(app_id, channel)
 
@@ -203,7 +204,7 @@ class W3DHub
     def auto_import_win32_registry(app_id, channel_id, registry_path = nil)
       return unless W3DHub.windows?
 
-      puts "Importing: #{app_id}-#{channel_id}"
+      logger.info(LOG_TAG) { "Importing: #{app_id}-#{channel_id}" }
 
       require "win32/registry"
 
@@ -234,7 +235,12 @@ class W3DHub
         end
       rescue => e
         # puts e.class, e.message, e.backtrace
-        puts "    Failed to import #{app_id}-#{channel_id}" if e.is_a?(Win32::Registry::Error)
+        if Win32::Registry::Error
+          logger.warn(LOG_TAG) { "    Failed to import #{app_id}-#{channel_id}" }
+        else
+          logger.warn(LOG_TAG) { "    An error occurred while tying to import #{app_id}-#{channel_id}" }
+          logger.warn(LOG_TAG) { e }
+        end
 
         false
       end

lib/application_manager/task.rb

@@ -1,6 +1,8 @@
 class W3DHub
   class ApplicationManager
     class Task
+      LOG_TAG = "W3DHub::ApplicationManager::Task".freeze
+
       class FailFast < RuntimeError
       end
 
@@ -44,10 +46,6 @@ class W3DHub
         @task_state
       end
 
-      def log(string)
-        puts string if W3DHUB_DEBUG
-      end
-
       # Start task, inside its own thread
       # FIXME: Ruby 3 has parallelism now: Use a Ractor to do work on a seperate core to
       #        prevent the UI from locking up while doing computation heavy work, i.e building
@@ -59,11 +57,14 @@ class W3DHub
           Sync do
             begin
               status = execute_task
-            rescue RuntimeError => e
-              status = false
-              @task_failure_reason = e.message[0..512]
             rescue FailFast
               # no-op
+            rescue StandardError, ERRNO::EACCES => e
+              status = false
+              @task_failure_reason = e.message[0..512]
+
+              logger.error(LOG_TAG) { "Task #{type.inspect} failed for #{@application.name}" }
+              logger.error(LOG_TAG) { e }
             end
 
             # Force free some bytes
@@ -227,7 +228,7 @@ class W3DHub
         packages = []
 
         manifests.reverse.each do |manifest|
-          log "#{manifest.game}-#{manifest.type}: #{manifest.version} (#{manifest.base_version})"
+          logger.info(LOG_TAG) { "#{manifest.game}-#{manifest.type}: #{manifest.version} (#{manifest.base_version})" }
 
           manifest.files.each do |file|
             @files["#{file.name}:#{manifest.version}"] = file
@@ -296,7 +297,7 @@ class W3DHub
 
             unless File.exist?(file_path)
               rejected_files << { file: file, manifest_version: manifest.version }
-              log "[#{manifest.version}] File missing: #{file_path}"
+              logger.info(LOG_TAG) { "[#{manifest.version}] File missing: #{file_path}" }
               next
             end
 
@@ -309,19 +310,19 @@ class W3DHub
 
             f.close
 
-            log file.inspect if file.checksum.nil?
+            logger.info(LOG_TAG) { file.inspect } if file.checksum.nil?
 
             if digest.hexdigest.upcase == file.checksum.upcase
               accepted_files[safe_file_name] = manifest.version
-              log "[#{manifest.version}] Verified file: #{file_path}"
+              logger.info(LOG_TAG) { "[#{manifest.version}] Verified file: #{file_path}" }
             else
               rejected_files << { file: file, manifest_version: manifest.version }
-              log "[#{manifest.version}] File failed Verification: #{file_path}"
+              logger.info(LOG_TAG) { "[#{manifest.version}] File failed Verification: #{file_path}" }
             end
           end
         end
 
-        log "#{rejected_files.count} missing or corrupt files"
+        logger.info(LOG_TAG) { "#{rejected_files.count} missing or corrupt files" }
 
         selected_packages = []
         selected_packages_hash = {}
@@ -448,7 +449,7 @@ class W3DHub
 
       def unpack_packages(packages)
         path = Cache.install_path(@application, @channel)
-        log "Unpacking packages in '#{path}'..."
+        logger.info(LOG_TAG) { "Unpacking packages in '#{path}'..." }
         Cache.create_directories(path, true)
 
         @status.operations.clear
@@ -495,7 +496,7 @@ class W3DHub
 
             update_interface_task_status
           else
-            log "COMMAND FAILED!"
+            logger.info(LOG_TAG) { "COMMAND FAILED!" }
             fail!("Failed to unpack #{package.name}")
 
             break
@@ -535,7 +536,7 @@ class W3DHub
 
         @status.step = :mark_application_installed
 
-        log "#{@app_id} has been installed."
+        logger.info(LOG_TAG) { "#{@app_id} has been installed." }
       end
 
       #############
@@ -567,7 +568,7 @@ class W3DHub
       end
 
       def package_fetch(package, &block)
-        log "Downloading: #{package.category}:#{package.subcategory}:#{package.name}-#{package.version}"
+        logger.info(LOG_TAG) { "Downloading: #{package.category}:#{package.subcategory}:#{package.name}-#{package.version}" }
 
         Api.package(package) do |chunk, remaining_bytes, total_bytes|
           block&.call(chunk, remaining_bytes, total_bytes)
@@ -575,7 +576,7 @@ class W3DHub
       end
 
       def verify_package(package, &block)
-        log "Verifying: #{package.category}:#{package.subcategory}:#{package.name}-#{package.version}"
+        logger.info(LOG_TAG) { "Verifying: #{package.category}:#{package.subcategory}:#{package.name}-#{package.version}" }
 
         digest = Digest::SHA256.new
         path = Cache.package_path(package.category, package.subcategory, package.name, package.version)
@@ -586,7 +587,7 @@ class W3DHub
           operation&.value = "Verifying..."
 
         file_size = File.size(path)
-        log "    File size: #{file_size}"
+        logger.info(LOG_TAG) { "    File size: #{file_size}" }
         chunk_size = package.checksum_chunk_size
         chunks = package.checksum_chunks.size
 
@@ -611,11 +612,11 @@ class W3DHub
 
             if Digest::SHA256.new.hexdigest(chunk).upcase == checksum.upcase
               valid_at = chunk_start + read_length
-              # log "    Passed chunk: #{chunk_start}"
+              # logger.debug(LOG_TAG) { "    Passed chunk: #{chunk_start}" } # Only enable when deep diving to find a bug (VERBOSE)
               # package.partially_valid_at_bytes = valid_at
               package.partially_valid_at_bytes = chunk_start
             else
-              log "    FAILED chunk: #{chunk_start}"
+              logger.info(LOG_TAG) { "    FAILED chunk: #{chunk_start}" }
               break
             end
           end
@@ -629,25 +630,25 @@ class W3DHub
       end
 
       def unpack_package(package, path)
-        log "    #{package.name}:#{package.version}"
+        logger.info(LOG_TAG) { "    #{package.name}:#{package.version}" }
         package_path = Cache.package_path(package.category, package.subcategory, package.name, package.version)
 
-        log "      Running #{W3DHub.tar_command} command: #{W3DHub.tar_command} -xf \"#{package_path}\" -C \"#{path}\""
+        logger.info(LOG_TAG) { "      Running #{W3DHub.tar_command} command: #{W3DHub.tar_command} -xf \"#{package_path}\" -C \"#{path}\"" }
         return system("#{W3DHub.tar_command} -xf \"#{package_path}\" -C \"#{path}\"")
       end
 
       def apply_patch(package, path)
-        log "    #{package.name}:#{package.version}"
+        logger.info(LOG_TAG) { "    #{package.name}:#{package.version}" }
         package_path = Cache.package_path(package.category, package.subcategory, package.name, package.version)
         temp_path = "#{Store.settings[:package_cache_dir]}/temp"
         manifest_file = package.custom_is_patch
 
         Cache.create_directories(temp_path, true)
 
-        log "      Running #{W3DHub.tar_command} command: #{W3DHub.tar_command} -xf \"#{package_path}\" -C \"#{temp_path}\""
+        logger.info(LOG_TAG) { "      Running #{W3DHub.tar_command} command: #{W3DHub.tar_command} -xf \"#{package_path}\" -C \"#{temp_path}\"" }
         system("#{W3DHub.tar_command} -xf \"#{package_path}\" -C \"#{temp_path}\"")
 
-        log "      Loading #{temp_path}/#{manifest_file.name}.patch..."
+        logger.info(LOG_TAG) { "      Loading #{temp_path}/#{manifest_file.name}.patch..." }
         patch_mix = W3DHub::Mixer::Reader.new(file_path: "#{temp_path}/#{manifest_file.name}.patch", ignore_crc_mismatches: false)
         patch_info = JSON.parse(patch_mix.package.files.find { |f| f.name == ".w3dhub.patch" || f.name == ".bhppatch" }.data, symbolize_names: true)
 
@@ -655,16 +656,19 @@ class W3DHub
         # Fix borked data -> Data 'cause Windows don't care about capitalization
         repaired_path = "#{path}/#{manifest_file.name.sub('data', 'Data')}" unless File.exist?(repaired_path) && path
 
-        log "      Loading #{repaired_path}..."
+        logger.info(LOG_TAG) { "      Loading #{repaired_path}..." }
         target_mix = W3DHub::Mixer::Reader.new(file_path: repaired_path, ignore_crc_mismatches: false)
 
-        log "      Removing files..." if patch_info[:removedFiles].size.positive?
+        logger.info(LOG_TAG) { "      Removing files..." } if patch_info[:removedFiles].size.positive?
         patch_info[:removedFiles].each do |file|
+          logger.debug(LOG_TAG) { "        #{file}" }
           target_mix.package.files.delete_if { |f| f.name == file }
         end
 
-        log "      Adding/Updating files..." if patch_info[:updatedFiles].size.positive?
+        logger.info(LOG_TAG) { "      Adding/Updating files..." } if patch_info[:updatedFiles].size.positive?
         patch_info[:updatedFiles].each do |file|
+          logger.debug(LOG_TAG) { "        #{file}" }
+
           patch = patch_mix.package.files.find { |f| f.name == file }
           target = target_mix.package.files.find { |f| f.name == file }
 
@@ -676,7 +680,7 @@ class W3DHub
         end
 
 
-        log "      Writing updated #{repaired_path}..." if patch_info[:updatedFiles].size.positive?
+        logger.info(LOG_TAG) { "      Writing updated #{repaired_path}..." } if patch_info[:updatedFiles].size.positive?
         W3DHub::Mixer::Writer.new(file_path: repaired_path, package: target_mix.package, memory_buffer: true)
 
         FileUtils.remove_dir(temp_path)
@@ -693,7 +697,7 @@ class W3DHub
         # Force data/ to Data/
         return true unless File.exist?("#{path}/data") && File.directory?("#{path}/data")
 
-        log "      Moving #{path}/data/ to #{path}/Data/"
+        logger.info(LOG_TAG) { "      Moving #{path}/data/ to #{path}/Data/" }
 
         FileUtils.mv(Dir.glob("#{path}/data/**"), "#{path}/Data", force: true)
         FileUtils.remove_dir("#{path}/data", force: true)

lib/application_manager/tasks/importer.rb

@@ -1,6 +1,8 @@
 class W3DHub
   class ApplicationManager
     class Importer < Task
+      LOG_TAG = "W3DHub::ApplicationManager::Importer".freeze
+
       def type
         :importer
       end

lib/application_manager/tasks/installer.rb

@@ -1,6 +1,8 @@
 class W3DHub
   class ApplicationManager
     class Installer < Task
+      LOG_TAG = "W3DHub::ApplicationManager::Installer".freeze
+
       def type
         :installer
       end

lib/application_manager/tasks/repairer.rb

@@ -1,6 +1,8 @@
 class W3DHub
   class ApplicationManager
     class Repairer < Installer
+      LOG_TAG = "W3DHub::ApplicationManager::Repairer".freeze
+
       def type
         :repairer
       end

lib/application_manager/tasks/uninstaller.rb

@@ -1,6 +1,8 @@
 class W3DHub
   class ApplicationManager
     class Uninstaller < Task
+      LOG_TAG = "W3DHub::ApplicationManager::Uninstaller".freeze
+
       def type
         :uninstaller
       end

lib/application_manager/tasks/updater.rb

@@ -1,6 +1,8 @@
 class W3DHub
   class ApplicationManager
     class Updater < Installer
+      LOG_TAG = "W3DHub::ApplicationManager::Updater".freeze
+
       def type
         :updater
       end

lib/background_worker.rb

@@ -1,12 +1,16 @@
 class W3DHub
   class BackgroundWorker
+    LOG_TAG = "W3DHub::BackgroundWorker"
     @@instance = nil
     @@alive = false
 
     def self.create
       raise "BackgroundWorker instance already exists!" if @@instance
+      logger.info(LOG_TAG) { "Starting background job worker..." }
+
 
       @@alive = true
+      @@run = true
       @@instance = self.new
 
       Async do
@@ -18,20 +22,24 @@ class W3DHub
       @@instance
     end
 
+    def self.run?
+      @@run
+    end
+
     def self.alive?
       @@alive
     end
 
     def self.shutdown!
-      @@alive = false
+      @@run = false
     end
 
-    def self.job(job, callback)
+    def self.job(job, callback, error_handler = nil)
-      @@instance.add_job(Job.new(job, callback))
+      @@instance.add_job(Job.new(job: job, callback: callback, error_handler: error_handler))
     end
 
-    def self.foreground_job(job, callback)
+    def self.foreground_job(job, callback, error_handler = nil)
-      @@instance.add_job(Job.new(job, callback, true))
+      @@instance.add_job(Job.new(job: job, callback: callback, error_handler: error_handler, deliver_to_queue: true))
     end
 
     def initialize
@@ -39,17 +47,20 @@ class W3DHub
     end
 
     def handle_jobs
-      while BackgroundWorker.alive?
+      while BackgroundWorker.run?
         job = @jobs.shift
 
         begin
           job&.do
-        rescue => e
+        rescue => error
-          pp e
+          job&.raise_error(error)
         end
 
         sleep 0.1
       end
+
+      logger.info(LOG_TAG) { "Stopped background job worker." }
+      @@alive = false
     end
 
     def add_job(job)
@@ -57,9 +68,10 @@ class W3DHub
     end
 
     class Job
-      def initialize(job, callback, deliver_to_queue = false)
+      def initialize(job:, callback:, error_handler: nil, deliver_to_queue: false)
         @job = job
         @callback = callback
+        @error_handler = error_handler
 
         @deliver_to_queue = deliver_to_queue
       end
@@ -76,6 +88,11 @@ class W3DHub
           @callback.call(result)
         end
       end
+
+      def raise_error(error)
+        logger.error error
+        @error_handler&.call(error)
+      end
     end
   end
 end

lib/cache.rb

@@ -1,5 +1,7 @@
 class W3DHub
   class Cache
+    LOG_TAG = "W3DHub::Cache".freeze
+
     def self.path(uri)
       ext = File.basename(uri).split(".").last
 
@@ -54,7 +56,7 @@ class W3DHub
       headers = Api::FORM_ENCODED_HEADERS
       start_from_bytes = package.custom_partially_valid_at_bytes
 
-      puts "    Start from bytes: #{start_from_bytes} of #{package.size}"
+      logger.info(LOG_TAG) { "    Start from bytes: #{start_from_bytes} of #{package.size}" }
 
       create_directories(path)
 
@@ -92,7 +94,7 @@ class W3DHub
       headers["Authorization"] = "Bearer #{Store.account.access_token}" if Store.account
       start_from_bytes = package.custom_partially_valid_at_bytes
 
-      puts "    Start from bytes: #{start_from_bytes} of #{package.size}"
+      logger.info(LOG_TAG) { "    Start from bytes: #{start_from_bytes} of #{package.size}" }
 
       create_directories(path)
 

lib/states/boot.rb

@@ -1,6 +1,8 @@
 class W3DHub
   class States
     class Boot < CyberarmEngine::GuiState
+      LOG_TAG = "W3DHub::States::Boot".freeze
+
       def setup
         window.show_cursor = true
 
@@ -11,6 +13,7 @@ class W3DHub
         @fraction = 0.0
         @w3dhub_logo = get_image("#{GAME_ROOT_PATH}/media/icons/app.png")
         @tasks = {
+          # connectivity_check: { started: false, complete: false }, # HEAD connectivity-check.ubuntu.com or HEAD secure.w3dhub.com?
           refresh_user_token: { started: false, complete: false },
           service_status: { started: false, complete: false },
           applications: { started: false, complete: false },
@@ -64,8 +67,9 @@ class W3DHub
           account = Api::Account.new(Store.settings[:account, :data], {})
 
           if (account.access_token_expiry - Time.now) / 60 <= 60 * 3 # Refresh if token expires within 3 hours
-            puts "Refreshing user login..."
+            logger.info(LOG_TAG) { "Refreshing user login..." }
 
+            # TODO: Check without network
             Api.on_fiber(:refresh_user_login, account.refresh_token) do |refreshed_account|
               update_account_data(refreshed_account)
             end
@@ -108,7 +112,7 @@ class W3DHub
 
             @tasks[:service_status][:complete] = true
           else
-            @status_label.value = I18n.t(:"boot.w3dhub_service_is_down")
+            BackgroundWorker.foreground_job(-> {}, ->(_) { @status_label.value = I18n.t(:"boot.w3dhub_service_is_down") })
           end
         end
       end
@@ -123,7 +127,7 @@ class W3DHub
             @tasks[:applications][:complete] = true
           else
             # FIXME: Failed to retreive!
-            @status_label.value = "FAILED TO RETREIVE APPS LIST"
+            BackgroundWorker.foreground_job(-> {}, ->(_){ @status_label.value = "FAILED TO RETREIVE APPS LIST" })
           end
         end
       end

w3d_hub_linux_launcher.rb

@@ -1,16 +1,43 @@
+# Hint to SDL that we're not a game and that the system may sleep
 ENV["SDL_VIDEO_ALLOW_SCREENSAVER"] = "1"
 
+require "fileutils"
+require "digest"
+require "rexml"
+require "logger"
+
+class W3DHub
+  W3DHUB_DEBUG = ARGV.join.include?("--debug")
+
+  GAME_ROOT_PATH = File.expand_path(".", __dir__)
+  CACHE_PATH = "#{GAME_ROOT_PATH}/data/cache"
+  SETTINGS_FILE_PATH = "#{GAME_ROOT_PATH}/data/settings.json"
+
+  LOGGER = Logger.new("#{GAME_ROOT_PATH}/data/logs/w3d_hub_linux_launcher.log", "daily")
+  LOGGER.level = Logger::Severity::DEBUG # W3DHUB_DEBUG ? Logger::Severity::DEBUG : Logger::Severity::WARN
+
+  LOG_TAG = "W3DHubLinuxLauncher"
+end
+
+module Kernel
+  def logger
+    W3DHub::LOGGER
+  end
+end
+
 begin
   require_relative "../cyberarm_engine/lib/cyberarm_engine"
 rescue LoadError => e
-  puts "Failed to load local cyberarm_engine:"
+  logger.warn(W3D::LOG_TAG) { "Failed to load local cyberarm_engine:" }
-  pp e
+  logger.warn(W3D::LOG_TAG) { e }
 
   require "cyberarm_engine"
 end
-require "fileutils"
+
-require "digest"
+class W3DHub
-require "rexml"
+  EMPTY_IMAGE = Gosu::Image.from_blob(1, 1)
+  BLACK_IMAGE = Gosu::Image.from_blob(1, 1, "\x00\x00\x00\xff")
+end
 
 require "i18n"
 require "launchy"
@@ -23,20 +50,9 @@ require "async/http/endpoint"
 require "async/websocket/client"
 require "protocol/websocket/connection"
 
-I18n.load_path << Dir[File.expand_path("locales") + "/*.yml"]
+I18n.load_path << Dir["#{W3DHub::GAME_ROOT_PATH}/locales/*.yml"]
 I18n.default_locale = :en
 
-class W3DHub
-  W3DHUB_DEBUG = ARGV.join.include?("--debug")
-
-  GAME_ROOT_PATH = File.expand_path(".", __dir__)
-  CACHE_PATH = "#{GAME_ROOT_PATH}/data/cache"
-  SETTINGS_FILE_PATH = "#{GAME_ROOT_PATH}/data/settings.json"
-
-  EMPTY_IMAGE = Gosu::Image.from_blob(1, 1)
-  BLACK_IMAGE = Gosu::Image.from_blob(1, 1, "\x00\x00\x00\xff")
-end
-
 require_relative "lib/version"
 require_relative "lib/theme"
 require_relative "lib/common"
@@ -83,8 +99,19 @@ require_relative "lib/pages/login"
 require_relative "lib/pages/settings"
 require_relative "lib/pages/download_manager"
 
+logger.info(W3DHub::LOG_TAG) { "W3D Hub Linux Launcher v#{W3DHub::VERSION}" }
+
 Thread.new do
   W3DHub::BackgroundWorker.create
 end
 
+logger.info(W3DHub::LOG_TAG) { "Launching window..." }
 W3DHub::Window.new(width: 980, height: 720, borderless: false).show unless defined?(Ocra)
+W3DHub::BackgroundWorker.shutdown!
+
+# Wait for BackgroundWorker to return
+while W3DHub::BackgroundWorker.alive?
+  sleep 0.1
+end
+
+W3DHub::LOGGER&.close