Improved overall performance by using logger.debug { ... } instead of logger.debug(...). This decreases the LDAP import dry runtime by ~33%.

app/controllers/application_controller/authenticates.rb

@@ -47,7 +47,7 @@ module ApplicationController::Authenticates
 
     # already logged in, early exit
     if session.id && session[:user_id]
-      logger.debug 'session based auth check'
+      logger.debug { 'session based auth check' }
       user = User.lookup(id: session[:user_id])
       return authentication_check_prerequesits(user, 'session', auth_param) if user
     end
@@ -64,7 +64,7 @@ module ApplicationController::Authenticates
     # check http basic based authentication
     authenticate_with_http_basic do |username, password|
       request.session_options[:skip] = true # do not send a session cookie
-      logger.debug "http basic auth check '#{username}'"
+      logger.debug { "http basic auth check '#{username}'" }
       if Setting.get('api_password_access') == false
         raise Exceptions::NotAuthorized, 'API password access disabled!'
       end
@@ -74,7 +74,7 @@ module ApplicationController::Authenticates
 
     # check http token based authentication
     authenticate_with_http_token do |token_string, _options|
-      logger.debug "http token auth check '#{token_string}'"
+      logger.debug { "http token auth check '#{token_string}'" }
       request.session_options[:skip] = true # do not send a session cookie
       if Setting.get('api_token_access') == false
         raise Exceptions::NotAuthorized, 'API token access disabled!'
@@ -114,7 +114,7 @@ module ApplicationController::Authenticates
     token = Doorkeeper::OAuth::Token.from_bearer_authorization(request)
     if token
       request.session_options[:skip] = true # do not send a session cookie
-      logger.debug "oauth2 token auth check '#{token}'"
+      logger.debug { "oauth2 token auth check '#{token}'" }
       access_token = Doorkeeper::AccessToken.by_token(token)
 
       if !access_token
@@ -153,7 +153,7 @@ module ApplicationController::Authenticates
 
     current_user_set(user, auth_type)
     user_device_log(user, auth_type)
-    logger.debug "#{auth_type} for '#{user.login}'"
+    logger.debug { "#{auth_type} for '#{user.login}'" }
     true
   end
 end

app/controllers/long_polling_controller.rb

@@ -77,7 +77,7 @@ class LongPollingController < ApplicationController
         count = count - 1
         queue = Sessions.queue(client_id)
         if queue && queue[0]
-          logger.debug "send #{queue.inspect} to #{client_id}"
+          logger.debug { "send #{queue.inspect} to #{client_id}" }
           render json: queue
           return
         end

app/models/channel.rb

@@ -136,7 +136,7 @@ stream all accounts
     last_channels = []
 
     loop do
-      logger.debug 'stream controll loop'
+      logger.debug { 'stream controll loop' }
 
       current_channels = []
       channels = Channel.where('active = ? AND area LIKE ?', true, '%::Account')

app/models/channel/driver/facebook.rb

@@ -16,12 +16,12 @@ class Channel::Driver::Facebook
     @sync     = options['sync']
     @pages    = options['pages']
 
-    Rails.logger.debug 'facebook fetch started'
+    Rails.logger.debug { 'facebook fetch started' }
 
     fetch_feed
     disconnect
 
-    Rails.logger.debug 'facebook fetch completed'
+    Rails.logger.debug { 'facebook fetch completed' }
     notice = ''
     {
       result: 'ok',
@@ -104,7 +104,7 @@ returns
         # ignore older messages
         if (@channel.created_at - 15.days) > Time.zone.parse(post['created_time']) || older_import >= older_import_max
           older_import += 1
-          Rails.logger.debug "post to old: #{post['id']}/#{post['created_time']}"
+          Rails.logger.debug { "post to old: #{post['id']}/#{post['created_time']}" }
           next
         end
 

app/models/channel/driver/twitter.rb

@@ -53,7 +53,7 @@ returns
     @sync        = options[:sync]
     @channel     = channel
 
-    Rails.logger.debug 'twitter fetch started'
+    Rails.logger.debug { 'twitter fetch started' }
 
     fetch_mentions
     fetch_search
@@ -61,7 +61,7 @@ returns
 
     disconnect
 
-    Rails.logger.debug 'twitter fetch completed'
+    Rails.logger.debug { 'twitter fetch completed' }
 
     {
       result: 'ok',
@@ -317,7 +317,7 @@ returns
       next if search[:term] == '#'
       next if search[:group_id].blank?
       result_type = search[:type] || 'mixed'
-      Rails.logger.debug " - searching for '#{search[:term]}'"
+      Rails.logger.debug { " - searching for '#{search[:term]}'" }
       older_import = 0
       older_import_max = 20
       @rest_client.client.search(search[:term], result_type: result_type).collect do |tweet|
@@ -326,7 +326,7 @@ returns
         # ignore older messages
         if (@channel.created_at - 15.days) > tweet.created_at.dup.utc || older_import >= older_import_max
           older_import += 1
-          Rails.logger.debug "tweet to old: #{tweet.id}/#{tweet.created_at}"
+          Rails.logger.debug { "tweet to old: #{tweet.id}/#{tweet.created_at}" }
           next
         end
 
@@ -341,7 +341,7 @@ returns
   def fetch_mentions
     return if @sync[:mentions].blank?
     return if @sync[:mentions][:group_id].blank?
-    Rails.logger.debug ' - searching for mentions'
+    Rails.logger.debug { ' - searching for mentions' }
     older_import = 0
     older_import_max = 20
     @rest_client.client.mentions_timeline.each do |tweet|
@@ -350,7 +350,7 @@ returns
       # ignore older messages
       if (@channel.created_at - 15.days) > tweet.created_at.dup.utc || older_import >= older_import_max
         older_import += 1
-        Rails.logger.debug "tweet to old: #{tweet.id}/#{tweet.created_at}"
+        Rails.logger.debug { "tweet to old: #{tweet.id}/#{tweet.created_at}" }
         next
       end
       next if Ticket::Article.find_by(message_id: tweet.id)
@@ -362,7 +362,7 @@ returns
   def fetch_direct_messages
     return if @sync[:direct_messages].blank?
     return if @sync[:direct_messages][:group_id].blank?
-    Rails.logger.debug ' - searching for direct_messages'
+    Rails.logger.debug { ' - searching for direct_messages' }
     older_import = 0
     older_import_max = 20
     @rest_client.client.direct_messages(full_text: 'true').each do |tweet|
@@ -370,7 +370,7 @@ returns
       # ignore older messages
       if (@channel.created_at - 15.days) > tweet.created_at.dup.utc || older_import >= older_import_max
         older_import += 1
-        Rails.logger.debug "tweet to old: #{tweet.id}/#{tweet.created_at}"
+        Rails.logger.debug { "tweet to old: #{tweet.id}/#{tweet.created_at}" }
         next
       end
       next if Ticket::Article.find_by(message_id: tweet.id)
@@ -398,19 +398,19 @@ returns
     sleep 4
     12.times do |loop_count|
       if Ticket::Article.find_by(message_id: tweet.id)
-        Rails.logger.debug "Own tweet already imported, skipping tweet #{tweet.id}"
+        Rails.logger.debug { "Own tweet already imported, skipping tweet #{tweet.id}" }
         return true
       end
       count = Delayed::Job.where('created_at < ?', event_time).count
       break if count.zero?
       sleep_time = 2 * count
       sleep_time = 5 if sleep_time > 5
-      Rails.logger.debug "Delay importing own tweets - sleep #{sleep_time} (loop #{loop_count})"
+      Rails.logger.debug { "Delay importing own tweets - sleep #{sleep_time} (loop #{loop_count})" }
       sleep sleep_time
     end
 
     if Ticket::Article.find_by(message_id: tweet.id)
-      Rails.logger.debug "Own tweet already imported, skipping tweet #{tweet.id}"
+      Rails.logger.debug { "Own tweet already imported, skipping tweet #{tweet.id}" }
       return true
     end
     false

app/models/channel/email_parser.rb

@@ -349,7 +349,7 @@ class Channel::EmailParser
           filename = $1
         end
       rescue
-        Rails.logger.debug 'Unable to get filename'
+        Rails.logger.debug { 'Unable to get filename' }
       end
     end
 
@@ -532,7 +532,7 @@ returns
       filters[setting.name] = Kernel.const_get(Setting.get(setting.name))
     end
     filters.each do |key, backend|
-      Rails.logger.debug "run postmaster pre filter #{key}: #{backend}"
+      Rails.logger.debug { "run postmaster pre filter #{key}: #{backend}" }
       begin
         backend.run(channel, mail)
       rescue => e
@@ -684,7 +684,7 @@ returns
       filters[setting.name] = Kernel.const_get(Setting.get(setting.name))
     end
     filters.each_value do |backend|
-      Rails.logger.debug "run postmaster post filter #{backend}"
+      Rails.logger.debug { "run postmaster post filter #{backend}" }
       begin
         backend.run(channel, mail, ticket, article, session_user)
       rescue => e

app/models/channel/filter/bounce_follow_up_check.rb

@@ -20,7 +20,7 @@ module Channel::Filter::BounceFollowUpCheck
       article = Ticket::Article.where(message_id_md5: message_id_md5).order('created_at DESC, id DESC').limit(1).first
       next if !article
 
-      Rails.logger.debug "Follow up for '##{article.ticket.number}' in bounce email."
+      Rails.logger.debug { "Follow up for '##{article.ticket.number}' in bounce email." }
       mail[ 'x-zammad-ticket-id'.to_sym ] = article.ticket_id
       mail[ 'x-zammad-is-auto-response'.to_sym ] = true
 

app/models/channel/filter/follow_up_check.rb

@@ -9,7 +9,7 @@ module Channel::Filter::FollowUpCheck
     # get ticket# from subject
     ticket = Ticket::Number.check(mail[:subject])
     if ticket
-      Rails.logger.debug "Follow up for '##{ticket.number}' in subject."
+      Rails.logger.debug { "Follow up for '##{ticket.number}' in subject." }
       mail['x-zammad-ticket-id'.to_sym] = ticket.id
       return true
     end
@@ -20,7 +20,7 @@ module Channel::Filter::FollowUpCheck
     if setting.include?('body')
       ticket = Ticket::Number.check(mail[:body])
       if ticket
-        Rails.logger.debug "Follow up for '##{ticket.number}' in body."
+        Rails.logger.debug { "Follow up for '##{ticket.number}' in body." }
         mail['x-zammad-ticket-id'.to_sym] = ticket.id
         return true
       end
@@ -32,7 +32,7 @@ module Channel::Filter::FollowUpCheck
         next if !attachment[:data]
         ticket = Ticket::Number.check(attachment[:data])
         next if !ticket
-        Rails.logger.debug "Follow up for '##{ticket.number}' in attachment."
+        Rails.logger.debug { "Follow up for '##{ticket.number}' in attachment." }
         mail['x-zammad-ticket-id'.to_sym] = ticket.id
         return true
       end
@@ -58,7 +58,7 @@ module Channel::Filter::FollowUpCheck
           message_id_md5 = Digest::MD5.hexdigest(message_id)
           article = Ticket::Article.where(message_id_md5: message_id_md5).order('created_at DESC, id DESC').limit(1).first
           next if !article
-          Rails.logger.debug "Follow up for '##{article.ticket.number}' in references."
+          Rails.logger.debug { "Follow up for '##{article.ticket.number}' in references." }
           mail['x-zammad-ticket-id'.to_sym] = article.ticket_id
           return true
         end
@@ -97,7 +97,7 @@ module Channel::Filter::FollowUpCheck
           # if subject is different, it's no followup
           next if subject_to_check != article_first.subject
 
-          Rails.logger.debug "Follow up for '##{article.ticket.number}' in references with same subject as inital article."
+          Rails.logger.debug { "Follow up for '##{article.ticket.number}' in references with same subject as inital article." }
           mail['x-zammad-ticket-id'.to_sym] = article_first.ticket_id
           return true
         end

app/models/channel/filter/identify_sender.rb

@@ -9,9 +9,9 @@ module Channel::Filter::IdentifySender
     if customer_user_id.present?
       customer_user = User.lookup(id: customer_user_id)
       if customer_user
-        Rails.logger.debug "Took customer form x-zammad-ticket-customer_id header '#{customer_user_id}'."
+        Rails.logger.debug { "Took customer form x-zammad-ticket-customer_id header '#{customer_user_id}'." }
       else
-        Rails.logger.debug "Invalid x-zammad-ticket-customer_id header '#{customer_user_id}', no such user - take user from 'from'-header."
+        Rails.logger.debug { "Invalid x-zammad-ticket-customer_id header '#{customer_user_id}', no such user - take user from 'from'-header." }
       end
     end
 
@@ -70,9 +70,9 @@ module Channel::Filter::IdentifySender
     if session_user_id.present?
       session_user = User.lookup(id: session_user_id)
       if session_user
-        Rails.logger.debug "Took session form x-zammad-session-user-id header '#{session_user_id}'."
+        Rails.logger.debug { "Took session form x-zammad-session-user-id header '#{session_user_id}'." }
       else
-        Rails.logger.debug "Invalid x-zammad-session-user-id header '#{session_user_id}', no such user - take user from 'from'-header."
+        Rails.logger.debug { "Invalid x-zammad-session-user-id header '#{session_user_id}', no such user - take user from 'from'-header." }
       end
     end
     if !session_user

app/models/concerns/checks_client_notification.rb

@@ -29,7 +29,7 @@ class OwnModel < ApplicationModel
 
     # return if we run import mode
     return if Setting.get('import_mode')
-    logger.debug "#{self.class.name}.find(#{id}) notify created " + created_at.to_s
+    logger.debug { "#{self.class.name}.find(#{id}) notify created #{created_at}" }
     class_name = self.class.name
     class_name.gsub!(/::/, '')
     PushMessages.send(
@@ -61,7 +61,7 @@ class OwnModel < ApplicationModel
 
     # return if we run import mode
     return if Setting.get('import_mode')
-    logger.debug "#{self.class.name}.find(#{id}) notify UPDATED " + updated_at.to_s
+    logger.debug { "#{self.class.name}.find(#{id}) notify UPDATED #{updated_at}" }
     class_name = self.class.name
     class_name.gsub!(/::/, '')
     PushMessages.send(
@@ -93,7 +93,7 @@ class OwnModel < ApplicationModel
 
     # return if we run import mode
     return if Setting.get('import_mode')
-    logger.debug "#{self.class.name}.find(#{id}) notify TOUCH " + updated_at.to_s
+    logger.debug { "#{self.class.name}.find(#{id}) notify TOUCH #{updated_at}" }
     class_name = self.class.name
     class_name.gsub!(/::/, '')
     PushMessages.send(
@@ -124,7 +124,7 @@ class OwnModel < ApplicationModel
 
     # return if we run import mode
     return if Setting.get('import_mode')
-    logger.debug "#{self.class.name}.find(#{id}) notify DESTOY " + updated_at.to_s
+    logger.debug { "#{self.class.name}.find(#{id}) notify DESTOY #{updated_at}" }
     class_name = self.class.name
     class_name.gsub!(/::/, '')
     PushMessages.send(