From c60be2140ed59108581c5b0178a1b7c89256a235 Mon Sep 17 00:00:00 2001 From: Martin Edenhofer Date: Fri, 17 Aug 2018 09:48:12 +0200 Subject: [PATCH] Fixed issue #2193 - Puma performance is going worst if users with phone attribute are updated or new tickets are created. --- .../javascripts/app/controllers/cti.coffee | 16 +- app/models/cti/caller_id.rb | 31 ++- app/models/cti/log.rb | 104 ++++++---- .../integration_cti_controller_test.rb | 8 +- .../integration_sipgate_controller_test.rb | 8 +- test/unit/cti_caller_id_test.rb | 181 +++++++++++++++++- 6 files changed, 292 insertions(+), 56 deletions(-) diff --git a/app/assets/javascripts/app/controllers/cti.coffee b/app/assets/javascripts/app/controllers/cti.coffee index a637ad7e0..2689bc2df 100644 --- a/app/assets/javascripts/app/controllers/cti.coffee +++ b/app/assets/javascripts/app/controllers/cti.coffee @@ -25,6 +25,13 @@ class App.CTI extends App.Controller @delay(delay, 500, 'cti_list_push_render') 'cti_list_push' ) + @bind('cti_event', (data) => + return if data.state isnt 'newCall' + return if data.direction isnt 'in' + return if @switch() isnt true + @notify(data) + 'cti_event' + ) @bind('auth', (data) => @meta.counter = 0 ) @@ -71,6 +78,7 @@ class App.CTI extends App.Controller # render new caller list if data.list @list = data.list + @updateNavMenu() if @renderDone @renderCallerLog() return @@ -145,8 +153,8 @@ class App.CTI extends App.Controller if item.comment item.state_human += ", #{item.comment}" - if item.start && item.end - item.duration = format((Date.parse(item.end) - Date.parse(item.start))/1000) + if item.start_at && item.end_at + item.duration = format((Date.parse(item.end_at) - Date.parse(item.start_at))/1000) diff_in_min = ((Date.now() - Date.parse(item.created_at)) / 1000) / 60 if diff_in_min > 1 @@ -198,9 +206,9 @@ class App.CTI extends App.Controller counter: => count = 0 for item in @list - if item.state is 'hangup' && !item.done + if !item.done count++ - @meta.counter + count + @meta.counter = count switch: (state = undefined) => diff --git a/app/models/cti/caller_id.rb b/app/models/cti/caller_id.rb index 77e6a347c..42cdf5522 100644 --- a/app/models/cti/caller_id.rb +++ b/app/models/cti/caller_id.rb @@ -113,9 +113,31 @@ returns caller_ids = caller_ids.concat(local_caller_ids) end - # store caller ids - Cti::CallerId.where(object: model.to_s, o_id: record.id).destroy_all - caller_ids.each do |caller_id| + # search for caller ids to keep + caller_ids_to_add = [] + existing_record_ids = Cti::CallerId.where(object: model.to_s, o_id: record.id).pluck(:id) + caller_ids.uniq.each do |caller_id| + existing_record_id = Cti::CallerId.where( + object: model.to_s, + o_id: record.id, + caller_id: caller_id, + level: level, + user_id: user_id, + ).pluck(:id) + if existing_record_id[0] + existing_record_ids.delete(existing_record_id[0]) + next + end + caller_ids_to_add.push caller_id + end + + # delete not longer existing caller ids + existing_record_ids.each do |record_id| + Cti::CallerId.destroy(record_id) + end + + # create new caller ids + caller_ids_to_add.each do |caller_id| Cti::CallerId.maybe_add( caller_id: caller_id, level: level, @@ -251,10 +273,13 @@ returns end def update_cti_logs + return if object != 'User' UpdateCtiLogsByCallerJob.perform_later(caller_id) end def update_cti_logs_with_fg_optimization + return if object != 'User' + return if level != 'known' UpdateCtiLogsByCallerJob.perform_now(caller_id, limit: 20) UpdateCtiLogsByCallerJob.perform_later(caller_id, limit: 40, offset: 20) end diff --git a/app/models/cti/log.rb b/app/models/cti/log.rb index 0b55c8db1..aaeb5013e 100644 --- a/app/models/cti/log.rb +++ b/app/models/cti/log.rb @@ -4,13 +4,13 @@ module Cti store :preferences - after_create :push_event, :push_caller_list - after_update :push_event, :push_caller_list - after_destroy :push_event, :push_caller_list + after_create :push_incoming_call, :push_caller_list_update + after_update :push_incoming_call, :push_caller_list_update + after_destroy :push_caller_list_update =begin - Cti::Log.create( + Cti::Log.create!( direction: 'in', from: '007', from_comment: 'AAA', @@ -21,7 +21,7 @@ module Cti state: 'newCall', ) - Cti::Log.create( + Cti::Log.create!( direction: 'in', from: '007', from_comment: '', @@ -32,7 +32,7 @@ module Cti state: 'answer', ) - Cti::Log.create( + Cti::Log.create!( direction: 'in', from: '009', from_comment: '', @@ -45,13 +45,13 @@ module Cti example data, can be used for demo - Cti::Log.create( + Cti::Log.create!( direction: 'in', from: '4930609854180', from_comment: 'Franz Bauer', to: '4930609811111', to_comment: 'Bob Smith', - call_id: '00001', + call_id: '435452113', comment: '', state: 'newCall', done: false, @@ -69,13 +69,13 @@ example data, can be used for demo } ) - Cti::Log.create( + Cti::Log.create!( direction: 'out', from: '4930609854180', from_comment: 'Franz Bauer', to: '4930609811111', to_comment: 'Bob Smith', - call_id: '00002', + call_id: rand(999_999_999), comment: '', state: 'newCall', preferences: { @@ -92,13 +92,13 @@ example data, can be used for demo } ) - Cti::Log.create( + Cti::Log.create!( direction: 'in', from: '4930609854180', from_comment: 'Franz Bauer', to: '4930609811111', to_comment: 'Bob Smith', - call_id: '00003', + call_id: rand(999_999_999), comment: '', state: 'answer', preferences: { @@ -115,13 +115,13 @@ example data, can be used for demo } ) - Cti::Log.create( + Cti::Log.create!( direction: 'in', from: '4930609854180', from_comment: 'Franz Bauer', to: '4930609811111', to_comment: 'Bob Smith', - call_id: '00004', + call_id: rand(999_999_999), comment: '', state: 'hangup', comment: 'normalClearing', @@ -140,13 +140,13 @@ example data, can be used for demo } ) - Cti::Log.create( + Cti::Log.create!( direction: 'in', from: '4930609854180', from_comment: 'Franz Bauer', to: '4930609811111', to_comment: 'Bob Smith', - call_id: '00005', + call_id: rand(999_999_999), comment: '', state: 'hangup', start_at: Time.zone.now - 15.seconds, @@ -165,13 +165,13 @@ example data, can be used for demo } ) - Cti::Log.create( + Cti::Log.create!( direction: 'in', from: '4930609854180', from_comment: 'Franz Bauer', to: '4930609811111', to_comment: '', - call_id: '00006', + call_id: rand(999_999_999), comment: '', state: 'hangup', start_at: Time.zone.now - 15.seconds, @@ -190,13 +190,13 @@ example data, can be used for demo } ) - Cti::Log.create( + Cti::Log.create!( direction: 'in', from: '4930609854180', from_comment: 'Franz Bauer', to: '4930609811111', to_comment: 'Bob Smith', - call_id: '00007', + call_id: rand(999_999_999), comment: '', state: 'hangup', start_at: Time.zone.now - 15.seconds, @@ -215,11 +215,11 @@ example data, can be used for demo } ) - Cti::Log.create( + Cti::Log.create!( direction: 'in', from: '4930609854180', to: '4930609811112', - call_id: '00008', + call_id: rand(999_999_999), comment: '', state: 'hangup', start_at: Time.zone.now - 20.seconds, @@ -236,14 +236,14 @@ example data, can be used for demo returns { - list: [...] - assets: {...} + list: [log_record1, log_record2, log_record3], + assets: {...}, } =end def self.log - list = Cti::Log.order('created_at DESC, id DESC').limit(60) + list = Cti::Log.log_records # add assets assets = list.map(&:preferences) @@ -259,6 +259,20 @@ returns } end +=begin + + Cti::Log.log_records + +returns + + [log_record1, log_record2, log_record3] + +=end + + def self.log_records + Cti::Log.order('created_at DESC, id DESC').limit(60) + end + =begin processes a incoming event @@ -269,7 +283,7 @@ Cti::Log.process( 'user' => 'user 1', 'from' => '4912347114711', 'to' => '4930600000000', - 'callId' => '4991155921769858278-1', # or call_id + 'callId' => '43545211', # or call_id 'direction' => 'in', ) @@ -287,6 +301,7 @@ Cti::Log.process( from_comment = nil to_comment = nil preferences = nil + done = true if params['direction'] == 'in' to_comment = user from_comment, preferences = CallerId.get_comment_preferences(params['from'], 'from') @@ -297,6 +312,9 @@ Cti::Log.process( case event when 'newCall' + if params['direction'] == 'in' + done = false + end create( direction: params['direction'], from: params['from'], @@ -308,6 +326,7 @@ Cti::Log.process( state: event, initialized_at: Time.zone.now, preferences: preferences, + done: done, ) when 'answer' log = find_by(call_id: call_id) @@ -318,16 +337,19 @@ Cti::Log.process( if user log.to_comment = user end + log.done = true log.comment = comment log.save when 'hangup' log = find_by(call_id: call_id) raise "No such call_id #{call_id}" if !log - if params['direction'] == 'in' && log.state == 'newCall' - log.done = false - end - if params['direction'] == 'in' && log.to_comment == 'voicemail' - log.done = false + log.done = done + if params['direction'] == 'in' + if log.state == 'newCall' + log.done = false + elsif log.to_comment == 'voicemail' + log.done = false + end end log.state = 'hangup' log.end_at = Time.zone.now @@ -343,7 +365,9 @@ Cti::Log.process( end end - def push_event + def push_incoming_call + return if state != 'newCall' + return if direction != 'in' users = User.with_permissions('cti.agent') users.each do |user| @@ -358,8 +382,17 @@ Cti::Log.process( end end - def push_caller_list - list = Cti::Log.log + def self.push_caller_list_update?(record) + list_ids = Cti::Log.log_records.pluck(:id) + if list_ids.present? + last_caller_log = Cti::Log.find_by(id: list_ids.last) + return false if last_caller_log && last_caller_log.created_at > record.created_at - 1.day + end + true + end + + def push_caller_list_update + return false if Cti::Log.push_caller_list_update?(self) users = User.with_permissions('cti.agent') users.each do |user| @@ -369,10 +402,11 @@ Cti::Log.process( user.id, { event: 'cti_list_push', - data: list, }, ) end + + true end =begin diff --git a/test/controllers/integration_cti_controller_test.rb b/test/controllers/integration_cti_controller_test.rb index 758ddb917..1305a35fe 100644 --- a/test/controllers/integration_cti_controller_test.rb +++ b/test/controllers/integration_cti_controller_test.rb @@ -279,7 +279,7 @@ class IntegrationCtiControllerTest < ActionDispatch::IntegrationTest assert_equal('CallerId Customer1', log.from_comment) assert_nil(log.comment) assert_equal('newCall', log.state) - assert_equal(true, log.done) + assert_equal(false, log.done) assert(log.initialized_at) assert_nil(log.start_at) assert_nil(log.end_at) @@ -339,7 +339,7 @@ class IntegrationCtiControllerTest < ActionDispatch::IntegrationTest assert_equal('CallerId Customer1', log.from_comment) assert_nil(log.comment) assert_equal('newCall', log.state) - assert_equal(true, log.done) + assert_equal(false, log.done) assert(log.initialized_at) assert_nil(log.start_at) assert_nil(log.end_at) @@ -399,7 +399,7 @@ class IntegrationCtiControllerTest < ActionDispatch::IntegrationTest assert_equal('CallerId Customer1', log.from_comment) assert_nil(log.comment) assert_equal('newCall', log.state) - assert_equal(true, log.done) + assert_equal(false, log.done) assert(log.initialized_at) assert_nil(log.start_at) assert_nil(log.end_at) @@ -441,7 +441,7 @@ class IntegrationCtiControllerTest < ActionDispatch::IntegrationTest assert(log.preferences['from']) assert_nil(log.comment) assert_equal('newCall', log.state) - assert_equal(true, log.done) + assert_equal(false, log.done) assert(log.initialized_at) assert_nil(log.start_at) assert_nil(log.end_at) diff --git a/test/controllers/integration_sipgate_controller_test.rb b/test/controllers/integration_sipgate_controller_test.rb index 4ce8412ef..97462d054 100644 --- a/test/controllers/integration_sipgate_controller_test.rb +++ b/test/controllers/integration_sipgate_controller_test.rb @@ -308,7 +308,7 @@ class IntegrationSipgateControllerTest < ActionDispatch::IntegrationTest assert_equal('CallerId Customer1', log.from_comment) assert_nil(log.comment) assert_equal('newCall', log.state) - assert_equal(true, log.done) + assert_equal(false, log.done) # inbound - I - answer by customer params = 'event=answer&direction=in&callId=1234567890-3&to=4930600000000&from=4912347114711' @@ -353,7 +353,7 @@ class IntegrationSipgateControllerTest < ActionDispatch::IntegrationTest assert_equal('CallerId Customer1', log.from_comment) assert_nil(log.comment) assert_equal('newCall', log.state) - assert_equal(true, log.done) + assert_equal(false, log.done) # inbound - II - answer by voicemail params = 'event=answer&direction=in&callId=1234567890-4&to=4930600000000&from=4912347114711&user=voicemail' @@ -398,7 +398,7 @@ class IntegrationSipgateControllerTest < ActionDispatch::IntegrationTest assert_equal('CallerId Customer1', log.from_comment) assert_nil(log.comment) assert_equal('newCall', log.state) - assert_equal(true, log.done) + assert_equal(false, log.done) # inbound - III - hangup by customer params = 'event=hangup&direction=in&callId=1234567890-5&cause=normalClearing&to=4930600000000&from=4912347114711' @@ -430,7 +430,7 @@ class IntegrationSipgateControllerTest < ActionDispatch::IntegrationTest assert(log.preferences['from']) assert_nil(log.comment) assert_equal('newCall', log.state) - assert_equal(true, log.done) + assert_equal(false, log.done) # get caller list get '/api/v1/cti/log' diff --git a/test/unit/cti_caller_id_test.rb b/test/unit/cti_caller_id_test.rb index 7a899f9e7..6eebb590a 100644 --- a/test/unit/cti_caller_id_test.rb +++ b/test/unit/cti_caller_id_test.rb @@ -7,13 +7,11 @@ class CtiCallerIdTest < ActiveSupport::TestCase Ticket.destroy_all Cti::CallerId.destroy_all - @agent1 = User.create_or_update( login: 'ticket-caller_id-agent1@example.com', firstname: 'CallerId', lastname: 'Agent1', email: 'ticket-caller_id-agent1@example.com', - password: 'agentpw', active: true, phone: '+49 1111 222222', fax: '+49 1111 222223', @@ -27,7 +25,6 @@ class CtiCallerIdTest < ActiveSupport::TestCase firstname: 'CallerId', lastname: 'Agent2', email: 'ticket-caller_id-agent2@example.com', - password: 'agentpw', phone: '+49 2222 222222', note: 'Phone at home: +49 2222 222224', active: true, @@ -39,7 +36,6 @@ class CtiCallerIdTest < ActiveSupport::TestCase firstname: 'CallerId', lastname: 'Agent3', email: 'ticket-caller_id-agent3@example.com', - password: 'agentpw', phone: '+49 2222 222222', active: true, updated_by_id: 1, @@ -51,12 +47,13 @@ class CtiCallerIdTest < ActiveSupport::TestCase firstname: 'CallerId', lastname: 'Customer1', email: 'ticket-caller_id-customer1@example.com', - password: 'customerpw', active: true, updated_by_id: 1, created_by_id: 1, ) + Observer::Transaction.commit + Scheduler.worker(true) end test '1 lookups' do @@ -132,7 +129,8 @@ Mob: +49 333 1112222", ) assert(ticket2) - Cti::CallerId.rebuild + Observer::Transaction.commit + Scheduler.worker(true) caller_ids = Cti::CallerId.lookup('491111222277') assert_equal(0, caller_ids.length) @@ -327,4 +325,175 @@ Mob: +49 333 8362222", end + test '4 touch caller log / don\'t touch caller log' do + 5.times do |count| + travel 2.seconds + Cti::Log.process( + 'cause' => '', + 'event' => 'newCall', + 'user' => 'user 1', + 'from' => '491111222222', + 'to' => '4930600000000', + 'callId' => "touch-loop-#{count}", + 'direction' => 'in', + ) + end + + # do not update Cti::Log on user touch + last_updated_at = Cti::Log.order(updated_at: :desc).first.updated_at + travel 10.minutes + @agent1.reload + @agent1.touch + Observer::Transaction.commit + Scheduler.worker(true) + assert_equal(last_updated_at, Cti::Log.order(updated_at: :desc).first.updated_at) + + # do update old Cti::Log on phone update of user + @agent1.reload + @agent1.phone = '+49 1111 222222 999' + @agent1.save! + Observer::Transaction.commit + Scheduler.worker(true) + assert_not_equal(last_updated_at, Cti::Log.order(updated_at: :desc).first.updated_at) + + # new call with not known number + travel 10.minutes + Cti::Log.process( + 'cause' => '', + 'event' => 'newCall', + 'user' => 'user 1', + 'from' => '49111122222277', + 'to' => '4930600000000', + 'callId' => 'touch-loop-20', + 'direction' => 'in', + ) + + # set not known number for agent1 + last_updated_at = Cti::Log.order(updated_at: :desc).first.updated_at + travel 10.minutes + @agent1.reload + @agent1.phone = '+49 1111 222222 77' + @agent1.save! + Observer::Transaction.commit + Scheduler.worker(true) + assert_not_equal(last_updated_at, Cti::Log.order(updated_at: :desc).first.updated_at) + + # verify last updated entry + last = Cti::Log.order(updated_at: :desc).first + assert_equal('49111122222277', last.preferences[:from][0][:caller_id]) + assert_nil(last.preferences[:from][0][:comment]) + assert_equal('known', last.preferences[:from][0][:level]) + assert_equal('User', last.preferences[:from][0][:object]) + assert_equal(@agent1.id, last.preferences[:from][0][:o_id]) + + # create new user with no phone number + last_updated_at = Cti::Log.order(updated_at: :desc).first.updated_at + travel 30.minutes + agent4 = User.create!( + login: 'ticket-caller_id-agent4@example.com', + firstname: 'CallerId', + lastname: 'Agent4', + email: 'ticket-caller_id-agent4@example.com', + active: true, + updated_by_id: 1, + created_by_id: 1, + ) + Observer::Transaction.commit + Scheduler.worker(true) + assert_equal(last_updated_at, Cti::Log.order(updated_at: :desc).first.updated_at) + + # verify if caller log is updated with '' value for phone + agent4.reload + agent4.phone = '' + agent4.save! + Observer::Transaction.commit + Scheduler.worker(true) + assert_equal(last_updated_at, Cti::Log.order(updated_at: :desc).first.updated_at) + + # verify if caller log is updated with nil value for phone + agent4.reload + agent4.phone = nil + agent4.save! + Observer::Transaction.commit + Scheduler.worker(true) + + # verify if caller log is updated with existing caller log value for phone + assert_equal(last_updated_at, Cti::Log.order(updated_at: :desc).first.updated_at) + agent4.reload + agent4.phone = '+49 1111 222222' + agent4.save! + Observer::Transaction.commit + Scheduler.worker(true) + assert_not_equal(last_updated_at, Cti::Log.order(updated_at: :desc).first.updated_at) + + # verify if caller log is no value change for phone + last_updated_at = Cti::Log.order(updated_at: :desc).first.updated_at + travel 30.minutes + agent4.save! + Observer::Transaction.commit + Scheduler.worker(true) + assert_equal(last_updated_at, Cti::Log.order(updated_at: :desc).first.updated_at) + + # verify if caller log is updated with '' value for phone + last_updated_at = Cti::Log.order(updated_at: :desc).first.updated_at + travel 30.minutes + agent4.reload + agent4.phone = '' + agent4.save! + Observer::Transaction.commit + Scheduler.worker(true) + assert_not_equal(last_updated_at, Cti::Log.order(updated_at: :desc).first.updated_at) + + # verify if caller log is updated if new ticket with existing caller id is created + last_updated_at = Cti::Log.order(updated_at: :desc).first.updated_at + travel 30.minutes + last_caller_id_count = Cti::CallerId.count + ticket1 = Ticket.create!( + title: 'some caller id test 1', + group: Group.lookup(name: 'Users'), + customer: @customer1, + state: Ticket::State.lookup(name: 'new'), + priority: Ticket::Priority.lookup(name: '2 normal'), + updated_by_id: @customer1.id, + created_by_id: @customer1.id, + ) + article1 = Ticket::Article.create!( + ticket_id: ticket1.id, + from: 'some_sender@example.com', + to: 'some_recipient@example.com', + subject: 'some subject', + message_id: 'some@id', + body: "some message\n+49 1111 222222", + internal: false, + sender: Ticket::Article::Sender.where(name: 'Customer').first, + type: Ticket::Article::Type.where(name: 'email').first, + updated_by_id: @customer1.id, + created_by_id: @customer1.id, + ) + Observer::Transaction.commit + Scheduler.worker(true) + assert_equal(last_caller_id_count + 2, Cti::CallerId.count) + assert_equal(last_updated_at, Cti::Log.order(updated_at: :desc).first.updated_at) + + end + + test '5 probe if caller log need to be pushed' do + + 60.times do |count| + travel 1.hour + Cti::Log.process( + 'cause' => '', + 'event' => 'newCall', + 'user' => 'user 1', + 'from' => '491111222222', + 'to' => '4930600000000', + 'callId' => "touch-loop-#{count}", + 'direction' => 'in', + ) + end + assert(Cti::Log.push_caller_list_update?(Cti::Log.last)) + assert_not(Cti::Log.push_caller_list_update?(Cti::Log.first)) + + end + end