From 24a59ef967bcd3e09da07a4a76ed2a6c12ba3e62 Mon Sep 17 00:00:00 2001
From: Henrik Nygren <nygrenh@gmail.com>
Date: Wed, 11 Nov 2026 09:23:49 +0200
Subject: [PATCH 1/5] Log per-user Kafka publishes at debug level

---
 lib/kafka_updater.rb | 22 +++++++++++-----------
 1 file changed, 11 insertions(+), 11 deletions(-)

diff --git a/lib/kafka_updater.rb b/lib/kafka_updater.rb
index da572c752..4d3307c91 100644
--- a/lib/kafka_updater.rb
+++ b/lib/kafka_updater.rb
@@ -29,7 +29,7 @@ def update_user_progress(task)
       return true
     end
     course = Course.find_by!(id: task.course_id)
-    Rails.logger.info("Publishing progress for user #{user.id} with moocfi id: #{course.moocfi_id}.")
+    Rails.logger.debug { "Publishing progress for user #{user.id} with moocfi id: #{course.moocfi_id}." }
     if !course.moocfi_id || course.moocfi_id.blank?
       Rails.logger.error('Cannot publish progress because moocfi id is not specified')
       return finished_successfully
@@ -39,7 +39,7 @@ def update_user_progress(task)
     available_points = AvailablePoint.course_sheet_points(course, parts)
     user_points = points_per_user[user.username]
     unless user_points
-      Rails.logger.info('No points found. Skipping')
+      Rails.logger.debug('No points found. Skipping')
       return true
     end
     progress = user_points.map do |group_name, awarded_points|
@@ -62,7 +62,7 @@ def update_user_progress(task)
     }
     topic = task.realtime ? 'user-course-progress-realtime' : 'user-course-progress-batch'
     make_kafka_request(topic, message)
-    Rails.logger.info("Publishing progress finished for user #{user.id}")
+    Rails.logger.debug { "Publishing progress finished for user #{user.id}" }
     finished_successfully = true
     finished_successfully
   end
@@ -86,7 +86,7 @@ def update_course_progress(task)
         Rails.logger.warn("KafkaUpdater#update_course_progress: no user for login=#{username.inspect} course_id=#{course.id}")
         next
       end
-      Rails.logger.info("Publishing progress for user #{current_user.id}")
+      Rails.logger.debug { "Publishing progress for user #{current_user.id}" }
       progress = points_by_group.map do |group_name, awarded_points|
         max_points = available_points[group_name] || 0
         stupid_name = "osa#{group_name.tr('^0-9', '').rjust(2, "0")}"
@@ -106,7 +106,7 @@ def update_course_progress(task)
         message_format_version: 1
       }
       make_kafka_request('user-course-progress-batch', message)
-      Rails.logger.info("Publishing progress finished for user #{current_user.id}")
+      Rails.logger.debug { "Publishing progress finished for user #{current_user.id}" }
     end
     Rails.logger.info("Batch publishing progress finished for course #{course.name}")
     finished_successfully = true
@@ -122,7 +122,7 @@ def update_user_points(task)
       return true
     end
     course = Course.find_by!(id: task.course_id)
-    Rails.logger.info("Publishing points for user #{user.id} with moocfi id: #{course.moocfi_id}.")
+    Rails.logger.debug { "Publishing points for user #{user.id} with moocfi id: #{course.moocfi_id}." }
     if !course.moocfi_id
       Rails.logger.error('Cannot publish points because moocfi id is not specified. Removing extra task (this task never should have been created.)')
       task.destroy!
@@ -145,7 +145,7 @@ def update_user_points(task)
     }
     topic = task.realtime ? 'user-points-realtime' : 'user-points-batch'
     make_kafka_request(topic, message)
-    Rails.logger.info("Publishing points finished for user #{user.id}")
+    Rails.logger.debug { "Publishing points finished for user #{user.id}" }
     finished_successfully = true
     finished_successfully
   end
@@ -169,7 +169,7 @@ def update_course_points(task)
         Rails.logger.warn("KafkaUpdater#update_course_points: no user for login=#{username.inspect} course_id=#{course.id}")
         next
       end
-      Rails.logger.info("Publishing points for user #{current_user.id}")
+      Rails.logger.debug { "Publishing points for user #{current_user.id}" }
       exercises_data = []
       exercises.map do |exercise|
         awarded_points = exercise.points_for(current_user)
@@ -200,7 +200,7 @@ def update_course_points(task)
         message_format_version: 1
       }
       make_kafka_request('user-course-points-batch', message)
-      Rails.logger.info("Publishing points finished for user #{current_user.id}")
+      Rails.logger.debug { "Publishing points finished for user #{current_user.id}" }
     end
     Rails.logger.info("Batch publishing points finished for course #{course.name}")
     finished_successfully = true
@@ -254,7 +254,7 @@ def update_user_course_points(task)
       return true
     end
     course = Course.find_by!(id: task.course_id)
-    Rails.logger.info("Publishing points for user #{user.id} with moocfi id: #{course.moocfi_id}.")
+    Rails.logger.debug { "Publishing points for user #{user.id} with moocfi id: #{course.moocfi_id}." }
     if !course.moocfi_id
       Rails.logger.error('Cannot publish points because moocfi id is not specified')
       return finished_successfully
@@ -290,7 +290,7 @@ def update_user_course_points(task)
     }
     topic = task.realtime ? 'user-course-points-realtime' : 'user-course-points-batch'
     make_kafka_request(topic, message)
-    Rails.logger.info("Publishing points finished for user #{user.id}")
+    Rails.logger.debug { "Publishing points finished for user #{user.id}" }
     finished_successfully = true
     finished_successfully
   end

From 7960428c730dd72d277ff1ba6e4fc850d71d363d Mon Sep 17 00:00:00 2001
From: Henrik Nygren <nygrenh@gmail.com>
Date: Wed, 11 Nov 2026 09:23:49 +0200
Subject: [PATCH 2/5] Apply the Rails log level to background task logs

---
 config/environments/production.rb | 4 ++--
 script/background_daemon          | 2 +-
 2 files changed, 3 insertions(+), 3 deletions(-)

diff --git a/config/environments/production.rb b/config/environments/production.rb
index 0f1cc3a53..8133118cd 100644
--- a/config/environments/production.rb
+++ b/config/environments/production.rb
@@ -58,8 +58,8 @@
   # Force all access to the app over SSL, use Strict-Transport-Security, and use secure cookies.
   # config.force_ssl = true
 
-  # Set to :debug to see everything in the log.
-  config.log_level = :info
+  # Set RAILS_LOG_LEVEL=debug to see everything in the log.
+  config.log_level = ENV.fetch('RAILS_LOG_LEVEL', 'info')
 
   # Prepend all log lines with the following tags.
   # config.log_tags = [ :subdomain, :uuid ]
diff --git a/script/background_daemon b/script/background_daemon
index f4b776f03..8b4a8a10c 100755
--- a/script/background_daemon
+++ b/script/background_daemon
@@ -45,7 +45,7 @@ processes = BackgroundTaskRegistry.all_tasks.map do |task|
   Process.fork do
     # Create individual logger for this task
     task_log_file = Rails.root.join('log', 'background_daemon', "#{task.class.name.underscore}.log")
-    task_logger = Logger.new(task_log_file)
+    task_logger = Logger.new(task_log_file, level: Rails.application.config.log_level)
     task_logger.formatter = proc do |severity, datetime, _progname, msg|
       "#{datetime}: #{severity} - #{msg}\n"
     end

From 70e7c7d1e36761fb00ab298538b3696892daa4e3 Mon Sep 17 00:00:00 2001
From: Henrik Nygren <nygrenh@gmail.com>
Date: Wed, 11 Nov 2026 09:30:36 +0200
Subject: [PATCH 3/5] Upsert user app data so concurrent updates can't collide

---
 app/controllers/api/v8/users_controller.rb    | 11 ++++--
 app/models/user_app_datum.rb                  | 12 ++++++
 lib/student_submission_migrator.rb            | 10 +----
 .../api/v8/users_controller_spec.rb           | 39 +++++++++++++++++++
 spec/lib/student_submission_migrator_spec.rb  | 12 ++++++
 5 files changed, 72 insertions(+), 12 deletions(-)

diff --git a/app/controllers/api/v8/users_controller.rb b/app/controllers/api/v8/users_controller.rb
index 40d491526..e087af746 100644
--- a/app/controllers/api/v8/users_controller.rb
+++ b/app/controllers/api/v8/users_controller.rb
@@ -392,10 +392,13 @@ def set_extra_data(user, eager_save = false)
           return if extra_fields.nil?
           namespace = extra_fields['namespace']
           raise 'Namespace not defined' unless namespace
-          extra_fields['data'].each do |key, value|
-            datum = user.user_app_data.find_or_initialize_by(namespace: namespace, field_name: key)
-            datum.value = value
-            datum.save! if eager_save
+          if eager_save
+            UserAppDatum.upsert_values(user_id: user.id, namespace: namespace, values_by_field_name: extra_fields['data'].to_unsafe_h)
+          else
+            extra_fields['data'].each do |key, value|
+              datum = user.user_app_data.find_or_initialize_by(namespace: namespace, field_name: key)
+              datum.value = value
+            end
           end
         end
 
diff --git a/app/models/user_app_datum.rb b/app/models/user_app_datum.rb
index ca01c6896..a8c099a70 100644
--- a/app/models/user_app_datum.rb
+++ b/app/models/user_app_datum.rb
@@ -2,5 +2,17 @@
 # frozen_string_literal: true
 
 class UserAppDatum < ApplicationRecord
+  extend T::Sig
+
   belongs_to :user
+
+  # Writes a persisted user's fields in one namespace atomically, so concurrent writes of the same field can't race to insert it.
+  sig { params(user_id: Integer, namespace: String, values_by_field_name: T::Hash[String, T.untyped]).void }
+  def self.upsert_values(user_id:, namespace:, values_by_field_name:)
+    return if values_by_field_name.empty?
+    rows = values_by_field_name.map do |field_name, value|
+      { user_id: user_id, namespace: namespace, field_name: field_name, value: value }
+    end
+    upsert_all(rows, unique_by: %i[user_id field_name namespace])
+  end
 end
diff --git a/lib/student_submission_migrator.rb b/lib/student_submission_migrator.rb
index 754806c47..6faee074c 100644
--- a/lib/student_submission_migrator.rb
+++ b/lib/student_submission_migrator.rb
@@ -100,14 +100,8 @@ def update_app_data
       return unless migration_entry['update_app_data']
       app_data_updates = migration_entry['update_app_data']
       app_data_updates.each do |adu|
-        namespace = adu['namespace']
-        adu['set_values'].each do |record|
-          field_name = record['field_name']
-          value = record['value']
-          db_record = UserAppDatum.find_or_initialize_by(namespace: namespace, field_name: field_name, user: @user)
-          db_record.value = value
-          db_record.save!
-        end
+        values_by_field_name = adu['set_values'].to_h { |record| [record['field_name'], record['value']] }
+        UserAppDatum.upsert_values(user_id: @user.id, namespace: adu['namespace'], values_by_field_name: values_by_field_name)
       end
     end
 end
diff --git a/spec/controllers/api/v8/users_controller_spec.rb b/spec/controllers/api/v8/users_controller_spec.rb
index 955555283..f60012d6f 100644
--- a/spec/controllers/api/v8/users_controller_spec.rb
+++ b/spec/controllers/api/v8/users_controller_spec.rb
@@ -179,6 +179,45 @@ def do_update(old_password)
     end
   end
 
+  describe 'PUT update extra fields' do
+    let!(:token) { Doorkeeper::AccessToken.create!(resource_owner_id: user.id, scopes: 'public') }
+
+    def do_update(data)
+      put :update, params: { id: 'current', user: { email: user.email, extra_fields: { namespace: 'ns', data: data } } }
+    end
+
+    def app_data_values
+      UserAppDatum.where(user: user, namespace: 'ns').pluck(:field_name, :value).to_h
+    end
+
+    it 'updates existing fields and adds new ones' do
+      existing = UserAppDatum.create!(user: user, namespace: 'ns', field_name: 'a', value: 'old', created_at: 1.day.ago, updated_at: 1.day.ago)
+
+      do_update(a: 'new', b: 'added')
+
+      expect(response).to have_http_status(200)
+      expect(app_data_values).to eq('a' => 'new', 'b' => 'added')
+      expect(existing.reload.created_at).to be_within(1.second).of(1.day.ago)
+      expect(existing.updated_at).to be_within(1.minute).of(Time.current)
+    end
+
+    it 'overwrites a field that a concurrent request created after this one started' do
+      competitor_inserted = false
+      allow(UserAppDatum).to receive(:new).and_wrap_original do |original, *args, **kwargs, &block|
+        unless competitor_inserted
+          competitor_inserted = true
+          UserAppDatum.insert!({ user_id: user.id, namespace: 'ns', field_name: 'a', value: 'concurrent' })
+        end
+        original.call(*args, **kwargs, &block)
+      end
+
+      do_update(a: 'mine')
+
+      expect(response).to have_http_status(200)
+      expect(app_data_values).to eq('a' => 'mine')
+    end
+  end
+
   describe 'DELETE destroy' do
     before :each do
       controller.current_user = admin
diff --git a/spec/lib/student_submission_migrator_spec.rb b/spec/lib/student_submission_migrator_spec.rb
index 335e6665f..43cb2fde4 100644
--- a/spec/lib/student_submission_migrator_spec.rb
+++ b/spec/lib/student_submission_migrator_spec.rb
@@ -66,6 +66,18 @@
     expect { expect(migrator.migration_is_allowed).to be(true) }.not_to output.to_stdout
   end
 
+  it 'sets the configured app data' do
+    UserAppDatum.create!(user: @user, namespace: 'ns', field_name: 'a', value: 'old')
+    allow(SiteSetting).to receive(:value).and_return([{
+      'from' => @course.id, 'to' => @other_course.id,
+      'update_app_data' => [{ 'namespace' => 'ns', 'set_values' => [{ 'field_name' => 'a', 'value' => 'new' }, { 'field_name' => 'b', 'value' => 'added' }] }]
+    }])
+
+    StudentSubmissionMigrator.new(@course, @other_course, @user).migrate!
+
+    expect(UserAppDatum.where(user: @user, namespace: 'ns').pluck(:field_name, :value).to_h).to eq('a' => 'new', 'b' => 'added')
+  end
+
   it 'throws exception if it cannot be migrated safely' do
     bad_course = FactoryBot.create(:course)
     allow(bad_course).to receive(:git_revision).and_return('other')

From c545a58118e14481e91e7027cf62e7683cd7a2af Mon Sep 17 00:00:00 2001
From: Henrik Nygren <nygrenh@gmail.com>
Date: Wed, 11 Nov 2026 12:14:29 +0200
Subject: [PATCH 4/5] Accept empty app data lists and upsert fields in a fixed
 order

---
 app/controllers/api/v8/users_controller.rb     |  7 +++++--
 app/models/user_app_datum.rb                   |  3 ++-
 .../api/v8/users_controller_spec.rb            | 18 ++++++++++++------
 3 files changed, 19 insertions(+), 9 deletions(-)

diff --git a/app/controllers/api/v8/users_controller.rb b/app/controllers/api/v8/users_controller.rb
index e087af746..114b32a3d 100644
--- a/app/controllers/api/v8/users_controller.rb
+++ b/app/controllers/api/v8/users_controller.rb
@@ -392,10 +392,13 @@ def set_extra_data(user, eager_save = false)
           return if extra_fields.nil?
           namespace = extra_fields['namespace']
           raise 'Namespace not defined' unless namespace
+          data = extra_fields['data']
+          # Some clients encode an empty map as [].
+          return if data.blank?
           if eager_save
-            UserAppDatum.upsert_values(user_id: user.id, namespace: namespace, values_by_field_name: extra_fields['data'].to_unsafe_h)
+            UserAppDatum.upsert_values(user_id: user.id, namespace: namespace, values_by_field_name: data.to_unsafe_h)
           else
-            extra_fields['data'].each do |key, value|
+            data.each do |key, value|
               datum = user.user_app_data.find_or_initialize_by(namespace: namespace, field_name: key)
               datum.value = value
             end
diff --git a/app/models/user_app_datum.rb b/app/models/user_app_datum.rb
index a8c099a70..a06988366 100644
--- a/app/models/user_app_datum.rb
+++ b/app/models/user_app_datum.rb
@@ -10,7 +10,8 @@ class UserAppDatum < ApplicationRecord
   sig { params(user_id: Integer, namespace: String, values_by_field_name: T::Hash[String, T.untyped]).void }
   def self.upsert_values(user_id:, namespace:, values_by_field_name:)
     return if values_by_field_name.empty?
-    rows = values_by_field_name.map do |field_name, value|
+    # Sorted so concurrent upserts lock the rows in the same order and can't deadlock.
+    rows = values_by_field_name.sort.map do |field_name, value|
       { user_id: user_id, namespace: namespace, field_name: field_name, value: value }
     end
     upsert_all(rows, unique_by: %i[user_id field_name namespace])
diff --git a/spec/controllers/api/v8/users_controller_spec.rb b/spec/controllers/api/v8/users_controller_spec.rb
index f60012d6f..b6455a52a 100644
--- a/spec/controllers/api/v8/users_controller_spec.rb
+++ b/spec/controllers/api/v8/users_controller_spec.rb
@@ -203,19 +203,25 @@ def app_data_values
 
     it 'overwrites a field that a concurrent request created after this one started' do
       competitor_inserted = false
-      allow(UserAppDatum).to receive(:new).and_wrap_original do |original, *args, **kwargs, &block|
-        unless competitor_inserted
-          competitor_inserted = true
-          UserAppDatum.insert!({ user_id: user.id, namespace: 'ns', field_name: 'a', value: 'concurrent' })
-        end
-        original.call(*args, **kwargs, &block)
+      allow(UserAppDatum).to receive(:upsert_all).and_wrap_original do |original, *args, **kwargs|
+        competitor_inserted = true
+        UserAppDatum.insert!({ user_id: user.id, namespace: 'ns', field_name: 'a', value: 'concurrent' })
+        original.call(*args, **kwargs)
       end
 
       do_update(a: 'mine')
 
+      expect(competitor_inserted).to be(true)
       expect(response).to have_http_status(200)
       expect(app_data_values).to eq('a' => 'mine')
     end
+
+    it 'accepts an empty data list' do
+      put :update, params: { id: 'current', user: { email: user.email, extra_fields: { namespace: 'ns', data: [] } } }, as: :json
+
+      expect(response).to have_http_status(200)
+      expect(app_data_values).to be_empty
+    end
   end
 
   describe 'DELETE destroy' do

From c60747a88db07f006b3ef0a9a41dfb4d1d4aaf21 Mon Sep 17 00:00:00 2001
From: Henrik Nygren <nygrenh@gmail.com>
Date: Wed, 11 Nov 2026 12:20:00 +0200
Subject: [PATCH 5/5] Build every background daemon logger with the app log
 level

---
 script/background_daemon                      | 25 ++++++++-----------
 .../api/v8/users_controller_spec.rb           | 10 ++++----
 2 files changed, 15 insertions(+), 20 deletions(-)

diff --git a/script/background_daemon b/script/background_daemon
index 8b4a8a10c..7e3ec4e03 100755
--- a/script/background_daemon
+++ b/script/background_daemon
@@ -19,20 +19,18 @@ def exception_to_str(e)
   e.message + "\n" + e.backtrace.join("\n        from ")
 end
 
-Dir.chdir root_dir
-require root_dir + '/config/environment'
-
-stdout_logger = Logger.new(STDOUT)
-stdout_logger.formatter = proc do |severity, datetime, _progname, msg|
-  "#{datetime}: #{severity} - #{msg}\n"
+def build_logger(target)
+  logger = Logger.new(target, level: Rails.application.config.log_level)
+  logger.formatter = proc do |severity, datetime, _progname, msg|
+    "#{datetime}: #{severity} - #{msg}\n"
+  end
+  logger
 end
 
-file_logger = Logger.new(Rails.root.join('log/background_daemon.log'))
-file_logger.formatter = proc do |severity, datetime, _progname, msg|
-  "#{datetime}: #{severity} - #{msg}\n"
-end
+Dir.chdir root_dir
+require root_dir + '/config/environment'
 
-Rails.logger = ActiveSupport::BroadcastLogger.new(stdout_logger, file_logger)
+Rails.logger = ActiveSupport::BroadcastLogger.new(build_logger(STDOUT), build_logger(Rails.root.join('log/background_daemon.log')))
 FileUtils.mkdir_p(Rails.root.join('log/background_daemon'))
 
 Rails.logger.auto_flushing = true if Rails.logger.respond_to? :auto_flushing=
@@ -45,10 +43,7 @@ processes = BackgroundTaskRegistry.all_tasks.map do |task|
   Process.fork do
     # Create individual logger for this task
     task_log_file = Rails.root.join('log', 'background_daemon', "#{task.class.name.underscore}.log")
-    task_logger = Logger.new(task_log_file, level: Rails.application.config.log_level)
-    task_logger.formatter = proc do |severity, datetime, _progname, msg|
-      "#{datetime}: #{severity} - #{msg}\n"
-    end
+    task_logger = build_logger(task_log_file)
     task_logger.auto_flushing = true if task_logger.respond_to? :auto_flushing=
 
     # Set up Rails logger for this process to use the task-specific logger
diff --git a/spec/controllers/api/v8/users_controller_spec.rb b/spec/controllers/api/v8/users_controller_spec.rb
index b6455a52a..9658a3f54 100644
--- a/spec/controllers/api/v8/users_controller_spec.rb
+++ b/spec/controllers/api/v8/users_controller_spec.rb
@@ -182,8 +182,8 @@ def do_update(old_password)
   describe 'PUT update extra fields' do
     let!(:token) { Doorkeeper::AccessToken.create!(resource_owner_id: user.id, scopes: 'public') }
 
-    def do_update(data)
-      put :update, params: { id: 'current', user: { email: user.email, extra_fields: { namespace: 'ns', data: data } } }
+    def do_update(data, **request_options)
+      put :update, params: { id: 'current', user: { email: user.email, extra_fields: { namespace: 'ns', data: data } } }, **request_options
     end
 
     def app_data_values
@@ -193,7 +193,7 @@ def app_data_values
     it 'updates existing fields and adds new ones' do
       existing = UserAppDatum.create!(user: user, namespace: 'ns', field_name: 'a', value: 'old', created_at: 1.day.ago, updated_at: 1.day.ago)
 
-      do_update(a: 'new', b: 'added')
+      do_update({ a: 'new', b: 'added' })
 
       expect(response).to have_http_status(200)
       expect(app_data_values).to eq('a' => 'new', 'b' => 'added')
@@ -209,7 +209,7 @@ def app_data_values
         original.call(*args, **kwargs)
       end
 
-      do_update(a: 'mine')
+      do_update({ a: 'mine' })
 
       expect(competitor_inserted).to be(true)
       expect(response).to have_http_status(200)
@@ -217,7 +217,7 @@ def app_data_values
     end
 
     it 'accepts an empty data list' do
-      put :update, params: { id: 'current', user: { email: user.email, extra_fields: { namespace: 'ns', data: [] } } }, as: :json
+      do_update([], as: :json)
 
       expect(response).to have_http_status(200)
       expect(app_data_values).to be_empty