Tickets getting switched to closed when replying (State not saved though)

Infos:

  • Used Zammad version: 5.0.2
  • Used Zammad installation type: package
  • Operating system: Ubuntu 20.04.3
  • Browser + version: Edge 95.0.1020.40 Also seeing on latest Chrome build

Expected behavior:

  • Reply to ticket via email
  • Click update
  • Email sent
  • No state change (Stay on tab is selected)

Actual behavior:

  • Reply to ticket via email
  • Click update
  • Email sent
  • State gets changed to closed, though not saved/updated on the ticket
  • Click “Discard your unsaved changes” and the ticket state is reverted to what it should be.

Steps to reproduce the behavior:

UPDATE:
To ensure this was not a macro or trigger issue, I have had the agents manually sort tickets and disabled all of the macros and triggers. The result is the issue is still sporadically happening when clicking update to send an email. It appears, after clicking update to send a reply, the email is sent and the state dropdown is toggled to closed, but not saved. To be clear, this is not initiated by the agent, but instead is just “occurring” after clicking update. If, after clicking update to send the email or update the ticket, an agent clicks the “Discard changes” button that shows up when the dropbox changes, the state reverts back to the correct state. For a few tickets, where the agent clicked update again after the dropbox changed to closed, the history says it was their user that made the change, not the system “–”.

I’m leaving all the previously posted information below in case it could be helpful

I am experiencing an odd issue where I reply to an email, the email is sent just fine, but after I click update, to send the email, the system proceeds to make an addition change of state to closed, but it does not get “saved” and instead it sits with the “Discard your unsaved changes” button available, as if I had not just clicked update. Additionally, this does not happen every time and seems to be intermittent, though occurring frequently.

As a bit of additional information, this tends to happen when a ticket has been worked on by a trigger, not a direct result of said trigger, but it seems to happen to the reply after a trigger has done its work and you then try to reply to said ticket. We are using triggers to move tickets through out our system and give them states, groups, tags appropriately. We are using the ticket state to trigger said triggers. As an example, we have a state called “transfer to billing” which changes the owner to “-” (Nobody), sets the state to new, and changes the group to billing. I included that as it may, though I doubt it, be pertinent.

It’s almost like the screen/script is making one last change, changing the state to closed, and not updating it. It is prudent to note, None of our triggers change the state of a ticket to closed, though they do change it to new/open as needed, and the behavior tab is set to “stay on tab”. I have included a screenshot of the logic of one of the triggers “Trigger Logic”, they are all the same, just with different groups.

GIF Example

zammad-animation

In the image above you can see me change the ticket using the state and triggers tied to it, additionally, at the end, you will see the state changed to closed out of nowhere. If you note, the “Discard your unsaved changes” button appears; If you were to click it, the state would change back to new, which is what it should have been. I did not get that part captured as I did not think about it, but can do so if someone thinks it might help.

Trigger Logic


This is an example trigger that we are/were using

UPDATE:
Just to see if it was an issue with using the state and the new core workflow update, I moved the logic to a macro and am experiencing the same thing as shown below.

Gif Example of Macro

zammad-animation-macro

Additionally, I tried removing the state change from the macro as we are still using the state dropdown to route tickets until this issue is sorted, without the change of state it does not result in the state being ticked to closed when applying the macro. Could there be some sort of a race condition that is causing the wrong item to be selected when the right hand pane of the ticket zoom, which in turn results in the script thinking it was changed?

I’m at a bit of a loss here and am leaning to this being a bug rather than a tech issue, any feedback is appreciated.

NOTE:
I know I have edited this post a number of times, but I’m just adding information to it instead of posting a new reply and cluttering things up, since nobody has replied yet I figure it should be OK.

1 Like

I tailed the production.log and tried to reproduce the error and was able to catch where the status changed from new to closed and I’m honestly not sure why. I’ve included the clip of the log.

production.log
W, [2021-11-05T02:55:01.949757 #939775-179480]  WARN -- : Scoped order is ignored, it's forced to be batch order.
I, [2021-11-05T02:55:02.470861 #939651-182460]  INFO -- : execute Job.run (try_count 0)...
I, [2021-11-05T02:55:02.472321 #939651-182460]  INFO -- : ended Job.run took: 0.083414632 seconds.
I, [2021-11-05T02:55:02.538544 #939775-179480]  INFO -- : Completed 200 OK in 938ms (Views: 3.2ms | ActiveRecord: 577.8ms | Allocations: 145111)
I, [2021-11-05T02:55:02.690587 #939775-179480]  INFO -- : Started GET "/api/v1/ticket_customer?customer_id=3362&_=1636080493460" for 71.226.94.214 at 2021-11-05 02:55:02 +0000
I, [2021-11-05T02:55:02.696603 #939775-179480]  INFO -- : Processing by TicketsController#ticket_customer as JSON
I, [2021-11-05T02:55:02.696695 #939775-179480]  INFO -- :   Parameters: {"customer_id"=>"3362", "_"=>"1636080493460"}
I, [2021-11-05T02:55:02.724628 #939775-179480]  INFO -- : Completed 200 OK in 28ms (Views: 1.5ms | ActiveRecord: 5.5ms | Allocations: 20097)
I, [2021-11-05T02:55:02.824062 #939762-173980]  INFO -- : Started GET "/api/v1/users/image/3074b1e501fedb1205c322607e753ece" for 71.226.94.214 at 2021-11-05 02:55:02 +0000
I, [2021-11-05T02:55:02.827676 #939762-173980]  INFO -- : Processing by UsersController#image as HTML
I, [2021-11-05T02:55:02.827722 #939762-173980]  INFO -- :   Parameters: {"hash"=>"3074b1e501fedb1205c322607e753ece"}
I, [2021-11-05T02:55:02.835915 #939762-173980]  INFO -- :   Rendering text template
I, [2021-11-05T02:55:02.835984 #939762-173980]  INFO -- :   Rendered text template (Duration: 0.0ms | Allocations: 1)
I, [2021-11-05T02:55:02.836055 #939762-173980]  INFO -- : Sent data avatar (0.4ms)
I, [2021-11-05T02:55:02.836789 #939762-173980]  INFO -- : Completed 200 OK in 9ms (Views: 0.3ms | ActiveRecord: 1.9ms | Allocations: 5579)
I, [2021-11-05T02:55:02.974220 #939762-173820]  INFO -- : Started DELETE "/api/v1/upload_caches/080957716" for 71.226.94.214 at 2021-11-05 02:55:02 +0000
I, [2021-11-05T02:55:02.977575 #939762-173820]  INFO -- : Processing by UploadCachesController#destroy as JSON
I, [2021-11-05T02:55:02.977620 #939762-173820]  INFO -- :   Parameters: {"id"=>"080957716"}
I, [2021-11-05T02:55:02.987065 #939762-173820]  INFO -- : Completed 200 OK in 9ms (Views: 0.1ms | ActiveRecord: 1.8ms | Allocations: 6657)
I, [2021-11-05T02:55:03.125969 #939762-173820]  INFO -- : Started POST "/api/v1/integration/smime" for 71.226.94.214 at 2021-11-05 02:55:03 +0000
I, [2021-11-05T02:55:03.132655 #939762-173820]  INFO -- : Processing by Integration::SMIMEController#search as JSON
I, [2021-11-05T02:55:03.132757 #939762-173820]  INFO -- :   Parameters: {"ticket"=>{"group_id"=>"1", "owner_id"=>"1", "state_id"=>"1", "priority_id"=>"2", "pending_time"=>nil}, "article"=>{"body"=>"[FILTERED]", "type"=>"note", "internal"=>true, "form_id"=>"080957716", "subtype"=>"", "in_reply_to"=>"", "to"=>"", "cc"=>"", "subject"=>"", "attachments"=>[]}}
I, [2021-11-05T02:55:03.667814 #939651-173940]  INFO -- : 2021-11-05T02:55:03+0000: [Worker(host:webhost005.XXXXthink.in pid:939651)] Job TicketUserTicketCounterJob [082ca1a9-78c1-435d-adcf-002c33e92337] from DelayedJob(default) with arguments: [3362, 3] (id=971513) (queue=default) RUNNINGorker(host:webhost005.XXXXthink.in pid:939651)] Job TicketUserTicketCounterJob [082ca1a9-78c1-435d-adcf-002c33e92337]
from DelayedJob(default) with arguments: [3362, 3] (id=971513) (queue=default) COMPLETED after 0.8636ost005.XXXXthink.in pid:939651)] Job TransactionJob [23b6f7a0-5ccd-428b-a196-e635ae62352e] from Delayed
Job(default) with arguments: [{"object"=>"Ticket", "object_id"=>10268, "user_id"=>3, "created_at"=>{"_aj_serialized"=>"ActiveJob::Serializers::TimeWithZoneSerializer", "value"=>"2021-11-05T02:55:01Z"}, "type"=>"update", "changes"=>{"group_id"=>[5, 1], "_aj_symbol_keys"=>[]}, "_aj_symbol_keys"=>["object", "object_id", "user_id", "created_at", "type", "changes"]}, {"interface_handle"=>"application_server", "_aj_symbol_keys"=>["interface_handle"]}] (id=971514) (queue=default) RUNNINGameters: {"key"=>"Ticket-10268", "client_id"=>"123", "callback"=>"TicketZoom", "state"=>{"ticket"=>{}, "article"=>{"form_id"=>"080957716"}}, "params
"=>{"ticket_id"=>10268, "overview_id"=>2, "shown"=>true}, "prio"=>3, "notify"=>false, "active"=>true, "attachments"=>[], "updated_at"=>"2021-11-05T02:53:45.513Z", "id"=>"39014"}8b-a196-e635ae62352e] from Delayed
Job(default) with arguments: [{"object"=>"Ticket", "object_id"=>10268, "user_id"=>3, "created_at"=>{"_aj_serialized"=>"ActiveJob::Serializers::TimeWithZoneSerializer", "value"=>"2021-11-05T02:55:01Z"}, "type"=>"update", "changes"=>{"group_id"=>[5, 1], "_aj_symbol_keys"=>[]}, "_aj_symbol_keys"=>["object", "object_id", "user_id", "created_at", "type", "changes"]}, {"interface_handle"=>"application_server", "_aj_symbol_keys"=>["interface_handle"]}] (id=971514) (queue=default) COMPLETED after 0.4268default) RUNNINGst:webhost005.XXXXthink.in pid:939651)] Job SearchIndexAssociationsJob [6cc66ff2-e277-49e1-a474-c4b259a0046f]
from DelayedJob(default) with arguments: ["Ticket", 10268] (id=971511) (queue=default) COMPLETED after 0.5800rogressivethink.in pid:939651)] Job SearchIndexJob [7cb56442-6546-4354-af71-c72cf389bf03] from Delayed
Job(default) with arguments: ["User", 3362] (id=971512) (queue=default) RUNNING000: [Worker(host:webhost005.XXXXthink.in pid:939651)] Job SearchIndexJob [7cb56442-6546-4354-af71-c72cf389bf03] from Delayed
Job(default) with arguments: ["User", 3362] (id=971512) (queue=default) COMPLETED after 0.4694..
I, [2021-11-05T02:55:10.563212 #939651-176660]  INFO -- : fetching imap (mail.XXXX.net/info@XXXX.net port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2021-11-05T02:55:10.591326 #939651-176660]  INFO -- :  - no message
I, [2021-11-05T02:55:10.737388 #939651-176660]  INFO -- : ended Channel.fetch took: 0.399124971 seconds.
I, [2021-11-05T02:55:10.737388 #939651-176660]  INFO -- : ended Channel.fetch took: 0.399124971 seconds.
I, [2021-11-05T02:55:12.206546 #939763-176120]  INFO -- : Started PUT "/api/v1/taskbar/39014" for 71.226.94.214 at 2021-11-05 02:55:12 +0000
I, [2021-11-05T02:55:12.216655 #939763-176120]  INFO -- : Processing by TaskbarController#update as JSON
I, [2021-11-05T02:55:12.216655 #939763-176120]  INFO -- : Processing by TaskbarController#update as JSON
I, [2021-11-05T02:55:12.216859 #939763-176120]  INFO -- :   Parameters: {"key"=>"Ticket-10268", "client_id"=>"123", "callback"=>"TicketZoom", "state"=>{"ticket"=>{}, "article"=>{"form_id"=>"080957716"}}, "params"=>{"ticket_id"=>10268, "overview_id"=>2, "shown"=>true}, "prio"=>3, "notify"=>false, "active"=>false, "attachments"=>[], "updated_at"=>"2021-11-05T02:53:45.513Z", "id"=>"39014"}
I, [2021-11-05T02:55:12.330019 #939763-176120]  INFO -- : Completed 200 OK in 113ms (Views: 0.6ms | ActiveRecord: 91.8ms | Allocations: 13472)
I, [2021-11-05T02:55:12.516650 #939763-176120]  INFO -- : Started PUT "/api/v1/taskbar/39015" for 71.226.94.214 at 2021-11-05 02:55:12 +0000
I, [2021-11-05T02:55:12.525268 #939763-176120]  INFO -- : Processing by TaskbarController#update as JSON
I, [2021-11-05T02:55:12.525427 #939763-176120]  INFO -- :   Parameters: {"key"=>"Ticket-10269", "client_id"=>"123", "callback"=>"TicketZoom", "state"=>{"ticket"=>{}, "article"=>{"form_id"=>"080961099"}}, "params"=>{"ticket_id"=>10269, "overview_id"=>2, "shown"=>true}, "prio"=>4, "notify"=>false, "active"=>true, "attachments"=>[], "updated_at"=>"2021-11-05T02:54:53.556Z", "id"=>"39015"}
I, [2021-11-05T02:55:12.924244 #939763-176120]  INFO -- : Completed 200 OK in 399ms (Views: 0.5ms | ActiveRecord: 375.8ms | Allocations: 13474)
I, [2021-11-05T02:55:14.292635 #939763-175980]  INFO -- : Started PUT "/api/v1/taskbar/39015" for 71.226.94.214 at 2021-11-05 02:55:14 +0000
I, [2021-11-05T02:55:14.296177 #939763-175980]  INFO -- : Processing by TaskbarController#update as JSON
I, [2021-11-05T02:55:14.296259 #939763-175980]  INFO -- :   Parameters: {"key"=>"Ticket-10269", "client_id"=>"123", "callback"=>"TicketZoom", "state"=>{"ticket"=>{}, "article"=>{"body"=>"[FILTERED]", "type"=>"email", "internal"=>false, "subtype"=>"reply", "in_reply_to"=>"<CAPZmVv+EQxe1G5V-GFeNOaxSe_MiOAmF=eqQbH6N6gf4-3-C5Q@mail.gmail.com>", "to"=>"XXXX@gmail.com", "from"=>"XXXX XXXX", "ticket_id"=>"10269", "content_type"=>"text/html", "sender_id"=>"1", "type_id"=>"1", "form_id"=>"080961099"}}, "params"=>{"ticket_id"=>10269, "overview_id"=>2, "shown"=>true}, "prio"=>4, "notify"=>false, "active"=>true, "attachments"=>[], "updated_at"=>"2021-11-05T02:54:53.556Z", "id"=>"39015"}
I, [2021-11-05T02:55:14.448220 #939763-175980]  INFO -- : Completed 200 OK in 152ms (Views: 0.5ms | ActiveRecord: 133.0ms | Allocations: 14302)
I, [2021-11-05T02:55:22.443349 #939651-5220]  INFO -- : Scheduler running...
I, [2021-11-05T02:55:22.448470 #939651-5220]  INFO -- : Running job thread for 'Process escalation tickets' (Ticket.process_escalation) status is: sleep
I, [2021-11-05T02:55:22.448773 #939651-5220]  INFO -- : Running job thread for 'Check Channels' (Channel.fetch) status is: sleep
I, [2021-11-05T02:55:22.448942 #939651-5220]  INFO -- : Running job thread for 'Check streams for Channel' (Channel.stream) status is: sleep
I, [2021-11-05T02:55:22.449063 #939651-5220]  INFO -- : Running job thread for 'Generate Session data' (Sessions.jobs) status is: sleep
I, [2021-11-05T02:55:22.877858 #939651-284300]  INFO -- : execute DataPrivacyTaskJob.perform_now (try_count 0)...
I, [2021-11-05T02:55:22.885013 #939651-284300]  INFO -- : ended DataPrivacyTaskJob.perform_now took: 0.434395409 seconds.
I, [2021-11-05T02:55:32.542448 #939651-284360]  INFO -- : execute Chat.cleanup_close (try_count 0)...
I, [2021-11-05T02:55:32.544742 #939651-284360]  INFO -- : ended Chat.cleanup_close took: 0.082583476 seconds.
I, [2021-11-05T02:55:40.850580 #939651-176660]  INFO -- : execute Channel.fetch (try_count 0)...
I, [2021-11-05T02:55:40.851555 #939651-176660]  INFO -- : fetching imap (mail.XXXX.net/info@XXXX.net port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2021-11-05T02:55:40.876340 #939651-176660]  INFO -- :  - no message
I, [2021-11-05T02:55:41.216182 #939651-176660]  INFO -- : ended Channel.fetch took: 0.477083965 seconds.
I, [2021-11-05T02:55:42.471378 #939651-5220]  INFO -- : Running job thread for 'Execute jobs' (Job.run) status is: sleep
I, [2021-11-05T02:56:08.070891 #939775-179640]  INFO -- : Started PUT "/api/v1/taskbar/39015" for 71.226.94.214 at 2021-11-05 02:56:08 +0000
I, [2021-11-05T02:56:08.082301 #939775-179640]  INFO -- : Processing by TaskbarController#update as JSON
I, [2021-11-05T02:56:08.082607 #939775-179640]  INFO -- :   Parameters: {"key"=>"Ticket-10269", "client_id"=>"123", "callback"=>"TicketZoom", "state"=>{"ticket"=>{}, "article"=>{"body"=>"[FILTERED]", "type"=>"email", "internal"=>false, "subtype"=>"reply", "in_reply_to"=>"<CAPZmVv+EQxe1G5V-GFeNOaxSe_MiOAmF=eqQbH6N6gf4-3-C5Q@mail.gmail.com>", "to"=>"XXXX@gmail.com", "from"=>"XXXX XXXX", "ticket_id"=>"10269", "content_type"=>"text/html", "sender_id"=>"1", "type_id"=>"1", "form_id"=>"080961099"}}, "params"=>{"ticket_id"=>10269, "overview_id"=>2, "shown"=>true}, "prio"=>4, "notify"=>false, "active"=>true, "attachments"=>[], "updated_at"=>"2021-11-05T02:54:53.556Z", "id"=>"39015"}
I, [2021-11-05T02:56:08.289183 #939775-179640]  INFO -- : Completed 200 OK in 206ms (Views: 0.3ms | ActiveRecord: 123.5ms | Allocations: 14812)
I, [2021-11-05T02:56:08.315452 #939775-173440]  INFO -- : Started PUT "/api/v1/tickets/10269?all=true" for 71.226.94.214 at 2021-11-05 02:56:08 +0000
I, [2021-11-05T02:56:08.322175 #939775-173440]  INFO -- : Processing by TicketsController#update as JSON
I, [2021-11-05T02:56:08.322254 #939775-173440]  INFO -- :   Parameters: {"number"=>"9110268", "title"=>"testing again", "group_id"=>"1", "owner_id"=>1, "customer_id"=>3, "state_id"=>"1", "priority_id"=>"2", "article"=>{"from"=>"XXXX XXXX", "to"=>"XXXX@gmail.com", "cc"=>"", "subject"=>"", "body"=>"[FILTERED]", "content_type"=>"text/html", "ticket_id"=>10269, "type_id"=>1, "sender_id"=>1, "internal"=>false, "in_reply_to"=>"<CAPZmVv+EQxe1G5V-GFeNOaxSe_MiOAmF=eqQbH6N6gf4-3-C5Q@mail.gmail.com>", "form_id"=>"080961099", "subtype"=>"reply"}, "updated_at"=>"2021-11-05T02:54:08.688Z", "preferences"=>{"channel_id"=>3}, "pending_time"=>nil, "id"=>"10269", "all"=>"true"}
W, [2021-11-05T02:56:08.571513 #939775-173440]  WARN -- : Scoped order is ignored, it's forced to be batch order.
I, [2021-11-05T02:56:09.077887 #939775-173440]  INFO -- : Completed 200 OK in 755ms (Views: 3.4ms | ActiveRecord: 423.6ms | Allocations: 190515)
I, [2021-11-05T02:56:09.404254 #939775-179560]  INFO -- : Started GET "/api/v1/users/image/3074b1e501fedb1205c322607e753ece" for 71.226.94.214 at 2021-11-05 02:56:09 +0000
I, [2021-11-05T02:56:09.411523 #939775-181260]  INFO -- : Started DELETE "/api/v1/upload_caches/080990915" for 71.226.94.214 at 2021-11-05 02:56:09 +0000
I, [2021-11-05T02:56:09.415417 #939775-179560]  INFO -- : Processing by UsersController#image as HTML
I, [2021-11-05T02:56:09.415478 #939775-179560]  INFO -- :   Parameters: {"hash"=>"3074b1e501fedb1205c322607e753ece"}
I, [2021-11-05T02:56:09.417017 #939775-181260]  INFO -- : Processing by UploadCachesController#destroy as JSON
I, [2021-11-05T02:56:09.417108 #939775-181260]  INFO -- :   Parameters: {"id"=>"080990915"}
I, [2021-11-05T02:56:09.431134 #939775-181260]  INFO -- : Completed 200 OK in 14ms (Views: 0.1ms | ActiveRecord: 4.4ms | Allocations: 11056)
I, [2021-11-05T02:56:09.433029 #939775-179560]  INFO -- :   Rendering text template
I, [2021-11-05T02:56:09.433236 #939775-179560]  INFO -- :   Rendered text template (Duration: 0.0ms | Allocations: 1)
I, [2021-11-05T02:56:09.433336 #939775-179560]  INFO -- : Sent data avatar (0.6ms)
I, [2021-11-05T02:56:09.435432 #939775-179560]  INFO -- : Completed 200 OK in 20ms (Views: 0.5ms | ActiveRecord: 8.5ms | Allocations: 14213)
I, [2021-11-05T02:56:09.705602 #939775-179480]  INFO -- : Started GET "/api/v1/tickets/10269?full=true&_=1636080493461" for 71.226.94.214 at 2021-11-05 02:56:09 +0000
I, [2021-11-05T02:56:09.713988 #939775-179480]  INFO -- : Processing by TicketsController#show as JSON
I, [2021-11-05T02:56:09.714035 #939775-179480]  INFO -- :   Parameters: {"full"=>"true", "_"=>"1636080493461", "id"=>"10269"}
I, [2021-11-05T02:56:09.731473 #939775-179480]  INFO -- : Completed 200 OK in 17ms (Views: 1.4ms | ActiveRecord: 3.6ms | Allocations: 16735)
I, [2021-11-05T02:56:09.804928 #939775-179480]  INFO -- : Started GET "/api/v1/users/3?full=true&_=1636080493462" for 71.226.94.214 at 2021-11-05 02:56:09 +0000
I, [2021-11-05T02:56:09.810397 #939775-179480]  INFO -- : Processing by UsersController#show as JSON
I, [2021-11-05T02:56:09.810456 #939775-179480]  INFO -- :   Parameters: {"full"=>"true", "_"=>"1636080493462", "id"=>"3"}
I, [2021-11-05T02:56:09.826185 #939775-179480]  INFO -- : Completed 200 OK in 16ms (Views: 1.3ms | ActiveRecord: 2.7ms | Allocations: 15477)
I, [2021-11-05T02:56:09.840523 #939775-179640]  INFO -- : Started POST "/api/v1/integration/smime" for 71.226.94.214 at 2021-11-05 02:56:09 +0000
I, [2021-11-05T02:56:09.840722 #939750-173440]  INFO -- : Started GET "/api/v1/ticket_customer?customer_id=3&_=1636080493463" for 71.226.94.214 at 2021-11-05 02:56:09 +0000
I, [2021-11-05T02:56:09.844862 #939775-179640]  INFO -- : Processing by Integration::SMIMEController#search as JSON
I, [2021-11-05T02:56:09.844943 #939775-179640]  INFO -- :   Parameters: {"ticket"=>{"group_id"=>"1", "owner_id"=>"", "state_id"=>"4", "priority_id"=>"2"}, "article"=>{"body"=>"[FILTERED]", "type"=>"note", "internal"=>true, "form_id"=>"080990915", "subtype"=>"", "in_reply_to"=>"", "to"=>"", "cc"=>"", "subject"=>"", "attachments"=>[]}}
I, [2021-11-05T02:56:09.845143 #939750-173440]  INFO -- : Processing by TicketsController#ticket_customer as JSON
I, [2021-11-05T02:56:09.845203 #939750-173440]  INFO -- :   Parameters: {"customer_id"=>"3", "_"=>"1636080493463"}
I, [2021-11-05T02:56:09.858143 #939775-179640]  INFO -- : Completed 200 OK in 13ms (Views: 0.2ms | ActiveRecord: 3.6ms | Allocations: 7735)
I, [2021-11-05T02:56:09.866087 #939762-173440]  INFO -- : Started GET "/api/v1/ticket_customer?customer_id=3&_=1636080493464" for 71.226.94.214 at 2021-11-05 02:56:09 +0000
I, [2021-11-05T02:56:09.869118 #939762-173440]  INFO -- : Processing by TicketsController#ticket_customer as JSON
I, [2021-11-05T02:56:09.869165 #939762-173440]  INFO -- :   Parameters: {"customer_id"=>"3", "_"=>"1636080493464"}
I, [2021-11-05T02:56:09.871794 #939750-173440]  INFO -- : Completed 200 OK in 27ms (Views: 3.4ms | ActiveRecord: 4.8ms | Allocations: 27744)
I, [2021-11-05T02:56:09.894084 #939762-173440]  INFO -- : Completed 200 OK in 25ms (Views: 3.6ms | ActiveRecord: 4.5ms | Allocations: 27740)
I, [2021-11-05T02:56:10.099889 #939762-175480]  INFO -- : Started GET "/api/v1/tickets/10269?all=true&_=1636080493465" for 71.226.94.214 at 2021-11-05 02:56:10 +0000
I, [2021-11-05T02:56:10.110697 #939762-175480]  INFO -- : Processing by TicketsController#show as JSON
I, [2021-11-05T02:56:10.110742 #939762-175480]  INFO -- :   Parameters: {"all"=>"true", "_"=>"1636080493465", "id"=>"10269"}
I, [2021-11-05T02:56:10.227848 #939762-175480]  INFO -- : Completed 200 OK in 117ms (Views: 7.2ms | ActiveRecord: 9.8ms | Allocations: 86129)
I, [2021-11-05T02:56:10.717167 #939762-175480]  INFO -- : Started GET "/api/v1/users/image/3074b1e501fedb1205c322607e753ece" for 71.226.94.214 at 2021-11-05 02:56:10 +0000
I, [2021-11-05T02:56:10.721893 #939762-175480]  INFO -- : Processing by UsersController#image as HTML
I, [2021-11-05T02:56:10.721948 #939762-175480]  INFO -- :   Parameters: {"hash"=>"3074b1e501fedb1205c322607e753ece"}
I, [2021-11-05T02:56:10.733714 #939762-175480]  INFO -- :   Rendering text template
I, [2021-11-05T02:56:10.733788 #939762-175480]  INFO -- :   Rendered text template (Duration: 0.0ms | Allocations: 1)
I, [2021-11-05T02:56:10.733867 #939762-175480]  INFO -- : Sent data avatar (0.4ms)
I, [2021-11-05T02:56:10.734696 #939762-175480]  INFO -- : Completed 200 OK in 13ms (Views: 0.3ms | ActiveRecord: 2.5ms | Allocations: 5578)
I, [2021-11-05T02:56:10.752243 #939651-173940]  INFO -- : 2021-11-05T02:56:10+0000: [Worker(host:webhost005.XXXXthink.in pid:939651)] Job TicketArticleCommunicateEmailJob [57b1ca16-6118-4057-9d9d-cb2fd2b1db7b] from DelayedJob(default) with arguments: [33166] (id=971517) (queue=default) RUNNING
I, [2021-11-05T02:56:11.055893 #939762-173980]  INFO -- : Started POST "/api/v1/integration/smime" for 71.226.94.214 at 2021-11-05 02:56:11 +0000
I, [2021-11-05T02:56:11.059063 #939762-173980]  INFO -- : Processing by Integration::SMIMEController#search as JSON
I, [2021-11-05T02:56:09.840722 #939750-173440]  INFO -- : Started GET "/api/v1/ticket_customer?customer_id=3&_=1636080493463" for 71.226.94.214 at 2021-11-05 02:56:09 +0000
I, [2021-11-05T02:56:09.844862 #939775-179640]  INFO -- : Processing by Integration::SMIMEController#search as JSON
I, [2021-11-05T02:56:09.844943 #939775-179640]  INFO -- :   Parameters: {"ticket"=>{"group_id"=>"1", "owner_id"=>"", "state_id"=>"4", "priority_id"=>"2"}, "article"=>{"body"=>"[FILTERED]", "type"=>"note", "internal"=>true, "form_id"=>"080990915", "subtype"=>"", "in_reply_to"=>"", "to"=>"", "cc"=>"", "subject"=>"", "attachments"=>[]}}
I, [2021-11-05T02:56:09.845143 #939750-173440]  INFO -- : Processing by TicketsController#ticket_customer as JSON
I, [2021-11-05T02:56:09.845203 #939750-173440]  INFO -- :   Parameters: {"customer_id"=>"3", "_"=>"1636080493463"}
I, [2021-11-05T02:56:09.858143 #939775-179640]  INFO -- : Completed 200 OK in 13ms (Views: 0.2ms | ActiveRecord: 3.6ms | Allocations: 7735)
I, [2021-11-05T02:56:09.866087 #939762-173440]  INFO -- : Started GET "/api/v1/ticket_customer?customer_id=3&_=1636080493464" for 71.226.94.214 at 2021-11-05 02:56:09 +0000
I, [2021-11-05T02:56:09.869118 #939762-173440]  INFO -- : Processing by TicketsController#ticket_customer as JSON
I, [2021-11-05T02:56:09.869165 #939762-173440]  INFO -- :   Parameters: {"customer_id"=>"3", "_"=>"1636080493464"}
I, [2021-11-05T02:56:09.871794 #939750-173440]  INFO -- : Completed 200 OK in 27ms (Views: 3.4ms | ActiveRecord: 4.8ms | Allocations: 27744)
I, [2021-11-05T02:56:09.894084 #939762-173440]  INFO -- : Completed 200 OK in 25ms (Views: 3.6ms | ActiveRecord: 4.5ms | Allocations: 27740)
I, [2021-11-05T02:56:10.099889 #939762-175480]  INFO -- : Started GET "/api/v1/tickets/10269?all=true&_=1636080493465" for 71.226.94.214 at 2021-11-05 02:56:10 +0000
I, [2021-11-05T02:56:10.110697 #939762-175480]  INFO -- : Processing by TicketsController#show as JSON
I, [2021-11-05T02:56:10.110742 #939762-175480]  INFO -- :   Parameters: {"all"=>"true", "_"=>"1636080493465", "id"=>"10269"}
I, [2021-11-05T02:56:10.227848 #939762-175480]  INFO -- : Completed 200 OK in 117ms (Views: 7.2ms | ActiveRecord: 9.8ms | Allocations: 86129)
I, [2021-11-05T02:56:10.717167 #939762-175480]  INFO -- : Started GET "/api/v1/users/image/3074b1e501fedb1205c322607e753ece" for 71.226.94.214 at 2021-11-05 02:56:10 +0000
I, [2021-11-05T02:56:10.721893 #939762-175480]  INFO -- : Processing by UsersController#image as HTML
I, [2021-11-05T02:56:10.721948 #939762-175480]  INFO -- :   Parameters: {"hash"=>"3074b1e501fedb1205c322607e753ece"}
I, [2021-11-05T02:56:10.733714 #939762-175480]  INFO -- :   Rendering text template
I, [2021-11-05T02:56:10.733788 #939762-175480]  INFO -- :   Rendered text template (Duration: 0.0ms | Allocations: 1)
I, [2021-11-05T02:56:10.733867 #939762-175480]  INFO -- : Sent data avatar (0.4ms)
I, [2021-11-05T02:56:10.734696 #939762-175480]  INFO -- : Completed 200 OK in 13ms (Views: 0.3ms | ActiveRecord: 2.5ms | Allocations: 5578)
I, [2021-11-05T02:56:10.752243 #939651-173940]  INFO -- : 2021-11-05T02:56:10+0000: [Worker(host:webhost005.XXXXthink.in pid:939651)] Job TicketArticleCommunicateEmailJob [57b1ca16-6118-4057-9d9d-cb2fd2b1db7b] from DelayedJob(default) with arguments: [33166] (id=971517) (queue=default) RUNNING
I, [2021-11-05T02:56:11.055893 #939762-173980]  INFO -- : Started POST "/api/v1/integration/smime" for 71.226.94.214 at 2021-11-05 02:56:11 +0000
I, [2021-11-05T02:56:11.059063 #939762-173980]  INFO -- : Processing by Integration::SMIMEController#search as JSON
I, [2021-11-05T02:56:11.059106 #939762-173980]  INFO -- :   Parameters: {"ticket"=>{"group_id"=>"1", "owner_id"=>"", "state_id"=>"4", "priority_id"=>"2"}, "article"=>{"body"=>"[FILTERED]", "type"=>"note", "internal"=>true, "form_id"=>"080990915", "subtype"=>"", "in_reply_to"=>"", "to"=>"", "cc"=>"", "subject"=>"", "attachments"=>[]}}
I, [2021-11-05T02:56:11.070161 #939762-173980]  INFO -- : Completed 200 OK in 11ms (Views: 0.1ms | ActiveRecord: 2.1ms | Allocations: 7736)
I, [2021-11-05T02:56:11.513655 #939651-176660]  INFO -- : execute Channel.fetch (try_count 0)...
I, [2021-11-05T02:56:11.515316 #939651-176660]  INFO -- : fetching imap (mail.XXXX.net/info@XXXX.net port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2021-11-05T02:56:11.545626 #939651-176660]  INFO -- :  - no message
I, [2021-11-05T02:56:11.950438 #939651-176660]  INFO -- : ended Channel.fetch took: 0.728739687 seconds.
I, [2021-11-05T02:56:12.044902 #939762-173820]  INFO -- : Started GET "/api/v1/ticket_articles/33166?full=true&_=1636080493466" for 71.226.94.214 at 2021-11-05 02:56:12 +0000
I, [2021-11-05T02:56:12.051427 #939762-173820]  INFO -- : Processing by TicketArticlesController#show as JSON
I, [2021-11-05T02:56:12.051518 #939762-173820]  INFO -- :   Parameters: {"full"=>"true", "_"=>"1636080493466", "id"=>"33166"}
I, [2021-11-05T02:56:12.073695 #939762-173820]  INFO -- : Completed 200 OK in 22ms (Views: 1.7ms | ActiveRecord: 3.8ms | Allocations: 18782)
I, [2021-11-05T02:56:12.458743 #939651-173940]  INFO -- : Send email to: 'XXXX@gmail.com' (from "XXXX XXXX via XXXX.net" <info@XXXX.net>)
I, [2021-11-05T02:56:12.894541 #939651-173940]  INFO -- : 2021-11-05T02:56:12+0000: [Worker(host:webhost005.XXXXthink.in pid:939651)] Job TicketArticleCommunicateEmailJob [57b1ca16-6118-4057-9d9d-cb2fd2b1db7b] from DelayedJob(default) with arguments: [33166] (id=971517) (queue=default) COMPLETED after 2.1421
I, [2021-11-05T02:56:12.969984 #939762-174740]  INFO -- : Started PUT "/api/v1/taskbar/39015" for 71.226.94.214 at 2021-11-05 02:56:12 +0000
I, [2021-11-05T02:56:12.981239 #939762-174740]  INFO -- : Processing by TaskbarController#update as JSON
I, [2021-11-05T02:56:12.981300 #939762-174740]  INFO -- :   Parameters: {"key"=>"Ticket-10269", "client_id"=>"123", "callback"=>"TicketZoom", "state"=>{"ticket"=>{"state_id"=>"4"}, "article"=>{"form_id"=>"080990915"}}, "params"=>{"ticket_id"=>10269, "overview_id"=>2, "shown"=>true}, "prio"=>4, "notify"=>false, "active"=>true, "attachments"=>[], "updated_at"=>"2021-11-05T02:54:53.556Z", "id"=>"39015"}
I, [2021-11-05T02:56:13.135181 #939651-173940]  INFO -- : 2021-11-05T02:56:13+0000: [Worker(host:webhost005.XXXXthink.in pid:939651)] Job TicketUserTicketCounterJob [9bcf44c3-9df7-4b72-aaef-37ef907c14d9] from DelayedJob(default) with arguments: [3, 3] (id=971518) (queue=default) RUNNING
I, [2021-11-05T02:56:13.170256 #939762-174740]  INFO -- : Completed 200 OK in 189ms (Views: 0.3ms | ActiveRecord: 171.7ms | Allocations: 14242)
I, [2021-11-05T02:56:13.624061 #939651-173940]  INFO -- : 2021-11-05T02:56:13+0000: [Worker(host:webhost005.XXXXthink.in pid:939651)] Job TicketUserTicketCounterJob [9bcf44c3-9df7-4b72-aaef-37ef907c14d9] from DelayedJob(default) with arguments: [3, 3] (id=971518) (queue=default) COMPLETED after 0.4886
I, [2021-11-05T02:56:13.688309 #939651-173940]  INFO -- : 2021-11-05T02:56:13+0000: [Worker(host:webhost005.XXXXthink.in pid:939651)] Job TransactionJob [3e48e733-18ed-43da-b02a-adabd2d00f71] from DelayedJob(default) with arguments: [{"object"=>"Ticket", "object_id"=>10269, "user_id"=>3, "created_at"=>{"_aj_serialized"=>"ActiveJob::Serializers::TimeWithZoneSerializer", "value"=>"2021-11-05T02:56:08Z"}, "type"=>"update", "changes"=>{"last_contact_agent_at"=>[{"_aj_serialized"=>"ActiveJob::Serializers::TimeWithZoneSerializer", "value"=>"2021-11-05T02:54:08Z"}, {"_aj_serialized"=>"ActiveJob::Serializers::TimeWithZoneSerializer", "value"=>"2021-11-05T02:56:08Z"}], "last_contact_at"=>[{"_aj_serialized"=>"ActiveJob::Serializers::TimeWithZoneSerializer", "value"=>"2021-11-05T02:54:08Z"}, {"_aj_serialized"=>"ActiveJob::Serializers::TimeWithZoneSerializer", "value"=>"2021-11-05T02:56:08Z"}], "last_owner_update_at"=>[{"_aj_serialized"=>"ActiveJob::Serializers::TimeWithZoneSerializer", "value"=>"2021-11-05T02:54:08Z"}, {"_aj_serialized"=>"ActiveJob::Serializers::TimeWithZoneSerializer", "value"=>"2021-11-05T02:56:08Z"}], "state_id"=>[1, 2], "_aj_symbol_keys"=>[]}, "article_id"=>33166, "_aj_symbol_keys"=>["object", "object_id", "user_id", "created_at", "type", "changes", "article_id"]}, {"interface_handle"=>"application_server", "_aj_symbol_keys"=>["interface_handle"]}] (id=971519) (queue=default) RUNNING
I, [2021-11-05T02:56:13.989035 #939651-173940]  INFO -- : 2021-11-05T02:56:13+0000: [Worker(host:webhost005.XXXXthink.in pid:939651)] Job TransactionJob [3e48e733-18ed-43da-b02a-adabd2d00f71] from DelayedJob(default) with arguments: [{"object"=>"Ticket", "object_id"=>10269, "user_id"=>3, "created_at"=>{"_aj_serialized"=>"ActiveJob::Serializers::TimeWithZoneSerializer", "value"=>"2021-11-05T02:56:08Z"}, "type"=>"update", "changes"=>{"last_contact_agent_at"=>[{"_aj_serialized"=>"ActiveJob::Serializers::TimeWithZoneSerializer", "value"=>"2021-11-05T02:54:08Z"}, {"_aj_serialized"=>"ActiveJob::Serializers::TimeWithZoneSerializer", "value"=>"2021-11-05T02:56:08Z"}], "last_contact_at"=>[{"_aj_serialized"=>"ActiveJob::Serializers::TimeWithZoneSerializer", "value"=>"2021-11-05T02:54:08Z"}, {"_aj_serialized"=>"ActiveJob::Serializers::TimeWithZoneSerializer", "value"=>"2021-11-05T02:56:08Z"}], "last_owner_update_at"=>[{"_aj_serialized"=>"ActiveJob::Serializers::TimeWithZoneSerializer", "value"=>"2021-11-05T02:54:08Z"}, {"_aj_serialized"=>"ActiveJob::Serializers::TimeWithZoneSerializer", "value"=>"2021-11-05T02:56:08Z"}], "state_id"=>[1, 2], "_aj_symbol_keys"=>[]}, "article_id"=>33166, "_aj_symbol_keys"=>["object", "object_id", "user_id", "created_at", "type", "changes", "article_id"]}, {"interface_handle"=>"application_server", "_aj_symbol_keys"=>["interface_handle"]}] (id=971519) (queue=default) COMPLETED after 0.3005
I, [2021-11-05T02:56:14.083581 #939651-173940]  INFO -- : 2021-11-05T02:56:14+0000: [Worker(host:webhost005.XXXXthink.in pid:939651)] Job SearchIndexAssociationsJob [809f0878-4ce2-4735-934e-b9ca59cc28eb] from DelayedJob(default) with arguments: ["Ticket", 10269] (id=971515) (queue=default) RUNNING
I, [2021-11-05T02:56:14.553631 #939651-173940]  INFO -- : 2021-11-05T02:56:14+0000: [Worker(host:webhost005.XXXXthink.in pid:939651)] Job SearchIndexAssociationsJob [809f0878-4ce2-4735-934e-b9ca59cc28eb] from DelayedJob(default) with arguments: ["Ticket", 10269] (id=971515) (queue=default) COMPLETED after 0.4698
I, [2021-11-05T02:56:14.614377 #939651-173940]  INFO -- : 2021-11-05T02:56:14+0000: [Worker(host:webhost005.XXXXthink.in pid:939651)] Job SearchIndexJob [da1968c5-fabc-4c93-8d85-3f99dcb35b8f] from DelayedJob(default) with arguments: ["User", 3] (id=971516) (queue=default) RUNNING
I, [2021-11-05T02:56:15.095917 #939651-173940]  INFO -- : 2021-11-05T02:56:15+0000: [Worker(host:webhost005.XXXXthink.in pid:939651)] Job SearchIndexJob [da1968c5-fabc-4c93-8d85-3f99dcb35b8f] from DelayedJob(default) with arguments: ["User", 3] (id=971516) (queue=default) COMPLETED after 0.4813
I, [2021-11-05T02:56:36.587368 #939762-173440]  INFO -- : Started PUT "/api/v1/taskbar/39015" for 71.226.94.214 at 2021-11-05 02:56:36 +0000
I, [2021-11-05T02:56:36.600469 #939762-173440]  INFO -- : Processing by TaskbarController#update as JSON
I, [2021-11-05T02:56:36.600715 #939762-173440]  INFO -- :   Parameters: {"key"=>"Ticket-10269", "client_id"=>"123", "callback"=>"TicketZoom", "state"=>{"ticket"=>{"state_id"=>"4"}, "article"=>{"form_id"=>"080990915"}}, "params"=>{"ticket_id"=>10269, "overview_id"=>2, "shown"=>true}, "prio"=>4, "notify"=>false, "active"=>false, "attachments"=>[], "updated_at"=>"2021-11-05T02:54:53.556Z", "id"=>"39015"}
I, [2021-11-05T02:56:36.921429 #939762-173440]  INFO -- : Completed 200 OK in 320ms (Views: 0.4ms | ActiveRecord: 261.1ms | Allocations: 13574)
I, [2021-11-05T02:56:42.259555 #939651-176660]  INFO -- : execute Channel.fetch (try_count 0)...
I, [2021-11-05T02:56:42.263627 #939651-176660]  INFO -- : fetching imap (mail.XXXX.net/info@XXXX.net port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2021-11-05T02:56:42.292448 #939651-176660]  INFO -- :  - no message
I, [2021-11-05T02:56:42.419229 #939651-176660]  INFO -- : ended Channel.fetch took: 0.466449869 seconds.
I, [2021-11-05T02:56:42.503296 #939651-5220]  INFO -- : Scheduler running...
I, [2021-11-05T02:56:42.508154 #939651-5220]  INFO -- : Running job thread for 'Process escalation tickets' (Ticket.process_escalation) status is: sleep
I, [2021-11-05T02:56:42.508444 #939651-5220]  INFO -- : Running job thread for 'Check Channels' (Channel.fetch) status is: sleep
I, [2021-11-05T02:56:42.508569 #939651-5220]  INFO -- : Running job thread for 'Check streams for Channel' (Channel.stream) status is: sleep
I, [2021-11-05T02:56:42.508676 #939651-5220]  INFO -- : Running job thread for 'Generate Session data' (Sessions.jobs) status is: sleep
I, [2021-11-05T02:56:42.510091 #939651-5220]  INFO -- : Running job thread for 'Execute jobs' (Job.run) status is: sleep
I, [2021-11-05T02:57:02.021922 #939762-175480]  INFO -- : Started PUT "/api/v1/taskbar/39015" for 71.226.94.214 at 2021-11-05 02:57:02 +0000
I, [2021-11-05T02:57:02.032278 #939762-175480]  INFO -- : Processing by TaskbarController#update as JSON

I’ve also noticed the state “new” is missing from the dropdown once the ticket has been updated as well. Is this normal as I do not recall it happening pre v.5.0 and am able to see it in the dropdown of a 4.x server. One more oddity, if I have a macro try to change the ticket state to new, I get an error “invalid value ‘1’ for field ‘state_id’!”

state-drop-down

invalid-state

To make this a bit clearer, and due to the fact that I’ve hit a character limit on the previous reply, here is a clip of the issue happening with a simple reply to a test email, again, no triggers or macros active/used. Notice the discard button and the dot next to the state, indicating that the change is not saved. If I click discard, you see the state change back to open as it should have been to begin with. If there is any more information I can give, to help this get some traction, please let me know as I’m happy to facilitate it. The worst part is this is intermittent, sometimes it happens other times it does not.

Just to make sure cache/extentions/plugins are not causing it, I have done this in a new install of chrome as well as in a “private/incognito” window and see the same result. This is also happening across different devices as well.

Ticket closed erroniously and back again after discard

zammad-closing

Just in case, the reason for the time stamp difference in the ticket screen, I originally did not record the clicking of the discord button, instead I was updating this post. I toggled back to the window and added to the recording.

And, just to make a bit clearer that something kosher is not going on here. I figured I would give the core workflow logic a try and see what would happen if I set the state to readonly for my user. As you can see below, once I assign my name, the state field is grayed out. Now, If I’m understanding this correctly, that should mean I can not change the option. However, once I reply to the email, you will see the state change to closed and still be readonly. Even more interesting is the fact that the discard button shows up which means that state change is seen as triggered by me, even though I should not have access according to the core workflow.

GIF of the state change happening despite a disabled state

zammad-closing-error-disabled-state

I have been able to solve this issue, it seems to have to do with the fact that new is no longer a valid ticket state once a ticket has been updated, this was not the case with v4 but is for v5. The solution was to use the core workflow to add the new option back to tickets, I’ll post a screen shot of what I used for edification/clarification once I’m able.

Hey there,
I was wondering if you could post a screenshot of your workflow that solves this issue?
We have the same problem in our zammad-instance. I also tried implementing a workflow to solve this, however, that did not work.
Regards,
Daniel

Sure thing,

Core Workflow

1 Like

In Zammad the state new is only available when they’re really new.
Upon the first agent reply the ticket in default configuration switches automatically to open.

At this point the state new is also removed from selections.
(We also indirectly point it out in the documentation: State — Zammad (for Agents) documentation)

If Zammad switches automatically to closed this is definitely not the way it should be.
This could be due a changed configuration on follow up states or may be a temporary issue with Core Workflows. We’ve been busy fine tuning Core Workflows in the last weeks, so the issue may also be indirectly solved if you update Zammad to the latest possible patchlevel.

Indeed, unfortunately v4.x did not remove the new option and we used it in our workflow (not too be confused with core workflow) so when v5 came along and removed the new state it was causing havoc. At this point the issue is resolved by using the core workflow to add back the new status.

We don’t use any workflow and also see this behaviour when we are setting a “new” ticket to any other status (including “open”): The status is set to “closed”. See threads #8195 and #8211 and the bug report at Changing ticket status from "new" to any other status always results in uncommited status "closed" · Issue #3880 · zammad/zammad · GitHub

1 Like