Zammad API sometimes returns Error 'No lookup value found for XXX'

LaVitaIT · June 17, 2021, 2:21pm

Hello Community,

We sometimes have an Issue with the API, most of the times it works fine but sometimes the user encounters an Error which I do not understand.

Used Zammad version: 4.0
Installation method: Package
Operating system: Ubuntu 18.04.5 LTS
Database + version: Postgresql 10
Elasticsearch version: 7.13.2
Browser + version: Chrome 91 Extension on Windows 10, accessing via API

Expected behavior:

We use a Google Chrome Extension that creates Tickets via the Zammad API.
It’s used to speed up the Ticket creation process for our Customer Service.
It sends a POST to “/api/v1/tickets”, which works most of the time.

Actual behavior:

Sometimes, the Request returns Error “No lookup value found for ‘priority’: 2” and no Ticket is created.

here is the log Message:

I, [2021-06-17T10:45:27.838427 #17730-47210069218960]  INFO -- : Started POST "/api/v1/tickets" for IPADDR at 2021-06-17 10:45:27 +0000
I, [2021-06-17T10:45:27.840850 #17730-47210069218960]  INFO -- : Processing by TicketsController#create as */*
I, [2021-06-17T10:45:27.840941 #17730-47210069218960]  INFO -- :   Parameters: {"type"=>"problem", "priority"=>2, "tags"=>"telefon,starface,telefonproblem,ZammadExtension", "customer"=>"poe", "group"=>1, "title"=>"title", "article"=>{"subject"=>"title", "body"=>"[FILTERED]", "type"=>"note", "internal"=>false}}
I, [2021-06-17T10:45:27.856042 #17730-47210069218960]  INFO -- : Enqueued UserDeviceLogJob (Job ID: b9e3f6b2-f528-4f4a-aff4-bb3107163a37) to DelayedJob(default) with arguments: "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.101 Safari/537.36", "IPADDR", 290, nil, "token_auth"
E, [2021-06-17T10:45:27.913581 #17730-47210069218960] ERROR -- : No lookup value found for 'priority': 2 (Exceptions::UnprocessableEntity)
/opt/zammad/app/models/application_model/can_associations.rb:381:in `block in association_name_to_id_convert'
/opt/zammad/app/models/application_model/can_associations.rb:349:in `map'
/opt/zammad/app/models/application_model/can_associations.rb:349:in `association_name_to_id_convert'
/opt/zammad/app/controllers/tickets_controller.rb:88:in `create'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/abstract_controller/base.rb:194:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_controller/metal/rendering.rb:30:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/opt/zammad/app/controllers/application_controller/has_secure_content_security_policy_for_downloads.rb:18:in `block (4 levels) in <module:HasSecureContentSecurityPolicyForDownloads>'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/notifications.rb:180:in `subscribed'
/opt/zammad/app/controllers/application_controller/has_secure_content_security_policy_for_downloads.rb:17:in `block (3 levels) in <module:HasSecureContentSecurityPolicyForDownloads>'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/notifications.rb:180:in `subscribed'
/opt/zammad/app/controllers/application_controller/has_secure_content_security_policy_for_downloads.rb:16:in `block (2 levels) in <module:HasSecureContentSecurityPolicyForDownloads>'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/callbacks.rb:118:in `instance_exec'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/opt/zammad/app/controllers/application_controller/handles_transitions.rb:14:in `handle_transaction'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/callbacks.rb:136:in `run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/abstract_controller/callbacks.rb:41:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_controller/metal/rescue.rb:22:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/notifications.rb:168:in `block in instrument'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/notifications.rb:168:in `instrument'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.6/lib/active_record/railties/controller_runtime.rb:24:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/abstract_controller/base.rb:134:in `process'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionview-5.2.4.6/lib/action_view/rendering.rb:32:in `process'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_controller/metal.rb:191:in `dispatch'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_controller/metal.rb:252:in `dispatch'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_dispatch/routing/route_set.rb:34:in `serve'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_dispatch/journey/router.rb:52:in `block in serve'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_dispatch/journey/router.rb:35:in `each'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_dispatch/journey/router.rb:35:in `serve'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_dispatch/routing/route_set.rb:840:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:420:in `call_app!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-saml-1.10.1/lib/omniauth/strategies/saml.rb:89:in `other_phase'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:190:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/builder.rb:45:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/tempfile_reaper.rb:15:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/etag.rb:27:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/conditional_get.rb:40:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_dispatch/middleware/cookies.rb:670:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/callbacks.rb:98:in `run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/railties-5.2.4.6/lib/rails/rack/logger.rb:38:in `call_app'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/railties-5.2.4.6/lib/rails/rack/logger.rb:26:in `block in call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/tagged_logging.rb:71:in `block in tagged'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/tagged_logging.rb:28:in `tagged'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/tagged_logging.rb:71:in `tagged'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/railties-5.2.4.6/lib/rails/rack/logger.rb:26:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_dispatch/middleware/executor.rb:14:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.6/lib/action_dispatch/middleware/static.rb:127:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/railties-5.2.4.6/lib/rails/engine.rb:524:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/puma-3.12.6/lib/puma/configuration.rb:227:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/puma-3.12.6/lib/puma/server.rb:706:in `handle_request'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/puma-3.12.6/lib/puma/server.rb:476:in `process_client'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/puma-3.12.6/lib/puma/server.rb:334:in `block in run'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/puma-3.12.6/lib/puma/thread_pool.rb:135:in `block in spawn_thread'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
I, [2021-06-17T10:45:27.914131 #17730-47210069218960]  INFO -- : Completed 422 Unprocessable Entity in 73ms (Views: 0.1ms | ActiveRecord: 7.0ms)

For comparison, here is the log for a successful Ticket creation:

I, [2021-06-17T11:02:40.693907 #17728-47210081619820]  INFO -- : Started POST "/api/v1/tickets" for IPADDR at 2021-06-17 11:02:40 +0000
I, [2021-06-17T11:02:40.696122 #17728-47210081619820]  INFO -- : Processing by TicketsController#create as */*
I, [2021-06-17T11:02:40.696186 #17728-47210081619820]  INFO -- :   Parameters: {"type"=>"problem", "priority"=>2, "tags"=>"telefon,starface,telefonproblem,ZammadExtension", "customer"=>"poe", "group"=>1, "title"=>"title", "article"=>{"subject"=>"title", "body"=>"[FILTERED]", "type"=>"note", "internal"=>false}}
I, [2021-06-17T11:02:40.711080 #17728-47210081619820]  INFO -- : Enqueued UserDeviceLogJob (Job ID: 0188b596-d8da-4a44-aacf-df4198abaa43) to DelayedJob(default) with arguments: "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.101 Safari/537.36", "IPADDR", 290, nil, "token_auth"
I, [2021-06-17T11:02:40.738642 #17728-47210081619820]  INFO -- : Enqueued SearchIndexJob (Job ID: 2c670adf-faa6-4da9-a96c-f756816c16b6) to DelayedJob(default) with arguments: "Ticket", 5306
I, [2021-06-17T11:02:40.741741 #17728-47210081619820]  INFO -- : Enqueued SearchIndexAssociationsJob (Job ID: a330b9e3-fce7-4e01-b4d3-292ef9b2cf35) to DelayedJob(default) with arguments: "Ticket", 5306
I, [2021-06-17T11:02:40.746973 #17728-47210081619820]  INFO -- : Enqueued SearchIndexJob (Job ID: 25ac3813-5abc-4164-bca6-a9d2e25db97d) to DelayedJob(default) with arguments: "User", 259
I, [2021-06-17T11:02:40.751524 #17728-47210081619820]  INFO -- : Enqueued SearchIndexJob (Job ID: d5405e53-a535-46bd-9111-398ec7736c82) to DelayedJob(default) with arguments: "Organization", 3
W, [2021-06-17T11:02:40.753558 #17728-47210081619820]  WARN -- : Scoped order is ignored, it's forced to be batch order.
I, [2021-06-17T11:02:40.758539 #17728-47210081619820]  INFO -- : Enqueued TicketUserTicketCounterJob (Job ID: 7e706833-4297-446a-989d-27f73c21d763) to DelayedJob(default) with arguments: 259, 259
I, [2021-06-17T11:02:40.770432 #17728-47210081619820]  INFO -- : Won't enqueue SearchIndexJob (Job ID: ff21db8b-7a45-4f1a-8c5b-8e1c58fd7900) because of already existing job with lock key 'SearchIndexJob/Ticket/5306'.
I, [2021-06-17T11:02:40.770510 #17728-47210081619820]  INFO -- : Enqueued SearchIndexJob (Job ID: ff21db8b-7a45-4f1a-8c5b-8e1c58fd7900) to DelayedJob(default) with arguments: "Ticket", 5306
I, [2021-06-17T11:02:40.777876 #17728-47210081619820]  INFO -- : Won't enqueue SearchIndexJob (Job ID: d07205b5-932d-4c05-a383-5d36f33ddd09) because of already existing job with lock key 'SearchIndexJob/Ticket/5306'.
I, [2021-06-17T11:02:40.777948 #17728-47210081619820]  INFO -- : Enqueued SearchIndexJob (Job ID: d07205b5-932d-4c05-a383-5d36f33ddd09) to DelayedJob(default) with arguments: "Ticket", 5306
I, [2021-06-17T11:02:40.785159 #17728-47210081619820]  INFO -- : Won't enqueue SearchIndexJob (Job ID: ed5e7f7a-8052-4f51-a405-9336ee5513ea) because of already existing job with lock key 'SearchIndexJob/Ticket/5306'.
I, [2021-06-17T11:02:40.785233 #17728-47210081619820]  INFO -- : Enqueued SearchIndexJob (Job ID: ed5e7f7a-8052-4f51-a405-9336ee5513ea) to DelayedJob(default) with arguments: "Ticket", 5306
I, [2021-06-17T11:02:40.792654 #17728-47210081619820]  INFO -- : Won't enqueue SearchIndexJob (Job ID: 46cff60b-22ad-459d-8980-64f39221b178) because of already existing job with lock key 'SearchIndexJob/Ticket/5306'.
I, [2021-06-17T11:02:40.792728 #17728-47210081619820]  INFO -- : Enqueued SearchIndexJob (Job ID: 46cff60b-22ad-459d-8980-64f39221b178) to DelayedJob(default) with arguments: "Ticket", 5306
I, [2021-06-17T11:02:40.817535 #17728-47210081619820]  INFO -- : Won't enqueue SearchIndexJob (Job ID: ce523b46-a629-48f6-8355-1589bedc3fd8) because of already existing job with lock key 'SearchIndexJob/Ticket/5306'.
I, [2021-06-17T11:02:40.817650 #17728-47210081619820]  INFO -- : Enqueued SearchIndexJob (Job ID: ce523b46-a629-48f6-8355-1589bedc3fd8) to DelayedJob(default) with arguments: "Ticket", 5306
I, [2021-06-17T11:02:40.818466 #17728-47210081619820]  INFO -- : Won't enqueue SearchIndexAssociationsJob (Job ID: 8996b1d7-97d6-4898-a4cc-77c91518e722) because of already existing job with lock key 'SearchIndexAssociationsJob/Ticket/5306'.
I, [2021-06-17T11:02:40.818546 #17728-47210081619820]  INFO -- : Enqueued SearchIndexAssociationsJob (Job ID: 8996b1d7-97d6-4898-a4cc-77c91518e722) to DelayedJob(default) with arguments: "Ticket", 5306
I, [2021-06-17T11:02:40.820789 #17728-47210081619820]  INFO -- : Won't enqueue SearchIndexJob (Job ID: 56b30faf-977e-4a8f-9ec7-b6e472724099) because of already existing job with lock key 'SearchIndexJob/User/259'.
I, [2021-06-17T11:02:40.820867 #17728-47210081619820]  INFO -- : Enqueued SearchIndexJob (Job ID: 56b30faf-977e-4a8f-9ec7-b6e472724099) to DelayedJob(default) with arguments: "User", 259
I, [2021-06-17T11:02:40.822593 #17728-47210081619820]  INFO -- : Won't enqueue SearchIndexJob (Job ID: 2228f81b-2252-4fa7-8195-e942eef78122) because of already existing job with lock key 'SearchIndexJob/Organization/3'.
I, [2021-06-17T11:02:40.822662 #17728-47210081619820]  INFO -- : Enqueued SearchIndexJob (Job ID: 2228f81b-2252-4fa7-8195-e942eef78122) to DelayedJob(default) with arguments: "Organization", 3
W, [2021-06-17T11:02:40.824866 #17728-47210081619820]  WARN -- : Scoped order is ignored, it's forced to be batch order.
I, [2021-06-17T11:02:40.826175 #17728-47210081619820]  INFO -- : Won't enqueue TicketUserTicketCounterJob (Job ID: 993d32f4-f447-44bd-884e-73f4dcbf8351) because of already existing job with lock key 'TicketUserTicketCounterJob/259/259'.
I, [2021-06-17T11:02:40.826653 #17728-47210081619820]  INFO -- : Enqueued TicketUserTicketCounterJob (Job ID: 993d32f4-f447-44bd-884e-73f4dcbf8351) to DelayedJob(default) with arguments: 259, 259
I, [2021-06-17T11:02:41.003284 #17728-47210081619820]  INFO -- : Execute trigger (Der Kunde hat mich nicht gehört/12) for this object (Ticket:5306/Loop:1)
I, [2021-06-17T11:02:41.005337 #17728-47210081619820]  INFO -- : NOTICE create - self.created_by_id is different: 259/1
I, [2021-06-17T11:02:41.011996 #17728-47210081619820]  INFO -- : Won't enqueue SearchIndexJob (Job ID: 4b8297fe-510c-4970-9e5a-a2fdb822d77a) because of already existing job with lock key 'SearchIndexJob/Ticket/5306'.
I, [2021-06-17T11:02:41.012109 #17728-47210081619820]  INFO -- : Enqueued SearchIndexJob (Job ID: 4b8297fe-510c-4970-9e5a-a2fdb822d77a) to DelayedJob(default) with arguments: "Ticket", 5306
I, [2021-06-17T11:02:41.027137 #17728-47210081619820]  INFO -- : Enqueued TransactionJob (Job ID: 2ae2cda2-05db-42a8-bc27-3e064e1463f9) to DelayedJob(default) with arguments: {:object=>"Tag", :object_id=>5649, :user_id=>1, :created_at=>#<GlobalID:0x000055dfe6d92580 @uri=#<URI::GID gid://zammad/Time/2021-06-17T11%3A02%3A41Z>>, :type=>"create"}, {:interface_handle=>"application_server", :type=>"create", :reset_user_id=>true, :disable=>["Transaction::Notification"], :trigger_ids=>{"5306"=>[12]}, :loop_count=>1}
W, [2021-06-17T11:02:41.036568 #17728-47210081619820]  WARN -- : Scoped order is ignored, it's forced to be batch order.
I, [2021-06-17T11:02:41.037968 #17728-47210081619820]  INFO -- : Won't enqueue TicketUserTicketCounterJob (Job ID: 6d23617f-ca53-40f8-9928-48f6114e0ece) because of already existing job with lock key 'TicketUserTicketCounterJob/259/259'.
I, [2021-06-17T11:02:41.038414 #17728-47210081619820]  INFO -- : Enqueued TicketUserTicketCounterJob (Job ID: 6d23617f-ca53-40f8-9928-48f6114e0ece) to DelayedJob(default) with arguments: 259, 259
I, [2021-06-17T11:02:41.041606 #17728-47210081619820]  INFO -- : Enqueued TransactionJob (Job ID: 614746b4-3421-4579-a846-fae1d2025e0a) to DelayedJob(default) with arguments: {:object=>"Ticket", :object_id=>5306, :user_id=>259, :created_at=>#<GlobalID:0x000055dfe7dee500 @uri=#<URI::GID gid://zammad/Time/2021-06-17T11%3A02%3A40Z>>, :type=>"create", :article_id=>30411}, {:interface_handle=>"application_server"}
I, [2021-06-17T11:02:41.044278 #17728-47210081619820]  INFO -- : Enqueued TransactionJob (Job ID: 619517b6-4d70-49e6-93ce-ad3a894c03d8) to DelayedJob(default) with arguments: {:object=>"Tag", :object_id=>5645, :user_id=>259, :created_at=>#<GlobalID:0x000055dfe7e4c1c8 @uri=#<URI::GID gid://zammad/Time/2021-06-17T11%3A02%3A40Z>>, :type=>"create"}, {:interface_handle=>"application_server"}
I, [2021-06-17T11:02:41.046672 #17728-47210081619820]  INFO -- : Enqueued TransactionJob (Job ID: 702d26a0-e686-4fe3-a155-2e2b8ee1db54) to DelayedJob(default) with arguments: {:object=>"Tag", :object_id=>5646, :user_id=>259, :created_at=>#<GlobalID:0x000055dfe7ea6268 @uri=#<URI::GID gid://zammad/Time/2021-06-17T11%3A02%3A40Z>>, :type=>"create"}, {:interface_handle=>"application_server"}
I, [2021-06-17T11:02:41.049053 #17728-47210081619820]  INFO -- : Enqueued TransactionJob (Job ID: b498f59b-ab0f-4fc9-ab7f-842090ae57af) to DelayedJob(default) with arguments: {:object=>"Tag", :object_id=>5647, :user_id=>259, :created_at=>#<GlobalID:0x000055dfe7eddcb8 @uri=#<URI::GID gid://zammad/Time/2021-06-17T11%3A02%3A40Z>>, :type=>"create"}, {:interface_handle=>"application_server"}
I, [2021-06-17T11:02:41.051448 #17728-47210081619820]  INFO -- : Enqueued TransactionJob (Job ID: 45708653-bd98-4620-91e0-7c5c1609b1bc) to DelayedJob(default) with arguments: {:object=>"Tag", :object_id=>5648, :user_id=>259, :created_at=>#<GlobalID:0x000055dfe7f1e0d8 @uri=#<URI::GID gid://zammad/Time/2021-06-17T11%3A02%3A40Z>>, :type=>"create"}, {:interface_handle=>"application_server"}
I, [2021-06-17T11:02:41.051569 #17728-47210081619820]  INFO -- : Completed 201 Created in 355ms (Views: 0.3ms | ActiveRecord: 58.3ms)

Steps to reproduce the behavior:

This happens with no obvious causes.
There is no high load when these Errors occour, and multiple people are having this issue.

MrGeneration · August 12, 2021, 4:43pm

You do have an actual priority named 2 ?
Or do you happen to trying to pick priority_id 2 ?

If this fails only sometimes, ensure that it’s not two different scripts causing that.
I don’t see why identical calls should fail.

LaVitaIT · August 17, 2021, 9:34am

Hello,

The priority_id is 2, the name is ‘Normal’.
The Ticket creation is done in only one script and in only one function, it will always have either priority: 2 or no Priority specified.

The Error is not reproducable - when sending the exact same Request a second time it sometimes works, sometimes doesn’t.
One time during testing I had the Error about 5 or 6 times in a row.

Also, as you can see in my Log for the failed request:
{"type"=>"problem", "priority"=>2, "tags"=>"telefon,starface,telefonproblem,ZammadExtension", "customer"=>"poe", "group"=>1, "title"=>"title", "article"=>{"subject"=>"title", "body"=>"[FILTERED]", "type"=>"note", "internal"=>false}}

and the log of the successful request:
{"type"=>"problem", "priority"=>2, "tags"=>"telefon,starface,telefonproblem,ZammadExtension", "customer"=>"poe", "group"=>1, "title"=>"title", "article"=>{"subject"=>"title", "body"=>"[FILTERED]", "type"=>"note", "internal"=>false}}

The Body is basically the same, I only changed the subject for simplicity.

Thank you for your assitance.

MrGeneration · August 31, 2021, 10:03am

Again, you’re using the attributes incorrect and may be just lucky at most parts because 2 normal being the default value. In some cases triggers however may be in your way.

Anyway:
Either use "priority_id": 2 - OR - "priority": "2 normal"

I threw over 20 test tickets against my test instance without issues when obeying above.

LaVitaIT · August 31, 2021, 11:25am

Ah, I see.
Could it be this changed in Version 4.0?

Anyways, thanks for your assitance.

MrGeneration · August 31, 2021, 12:28pm

No the payload on that regard didn’t change in between 3.x and 4.x as far as I’m aware.
Zammad may be more strict through.

system · December 29, 2021, 12:28pm

This topic was automatically closed 120 days after the last reply. New replies are no longer allowed.