Many duplicate users being created

AStatler · August 26, 2019, 3:21pm

Used Zammad version: 3.1
Used Zammad installation source: package
Operating system: Ubuntu 18.04
Browser + version: Chrome Version 76.0.3809.100 (Official Build) (64-bit)

Expected behavior: One user account being created.

Actual behavior: Many accounts being created.

Steps to reproduce the behavior: Unknown.

Being forthright I’m uncertain as to what is causing this issue. If it’s something in our agents workflow we can do to avoid that would be perfect.

We are getting a slew, ~7 accounts created for some new users we make for our internal ticket system.

Our workflow is thus: We receive an email or phone call, and then log each one manually. Making the user as whoever called in for help. The actual user never logs in themselves to our system, only the agents.

If anyone has some advice of what we are doing incorrectly I would much appreciate it.

Thank you.

MrGeneration · August 27, 2019, 2:15pm

Well the most interesting question would be: Where do those duplicate users come from?
Possible option is that your agents keep on creating new accounts because e.g. Zammad does not deliver any search results.

You need to identify the source.

Any integrations activated ?
Like LDAP or Exchange?

AStatler · August 28, 2019, 2:37pm

That is the most interesting question!
Admittedly I’m hoping it’s a boring answer such as: change the workflow, or uncheck that one box.

I could see one or two being made by accident, but we’re not even making more than a single ticket total for most of these additional duplicate users… which is why I’m so confused. That is, we have a single user who has one ticket, and then there are all those duplicates of their accounts that have no tickets assigned to them.

No integrations activated. The only external we have tied in is the email system and that is very sparsely used.

SEGGER-NV · August 29, 2019, 7:21am

Hello,

Do you create a new user for each phone call or do you create the user once and then reuse the original user for future phone call tickets?
Zammad uses e-mail as a unique identifier. So maybe your agents are creating the same user but with different e-mails each time as they e.g. don’t know it or something?

You have to make sure that once a user is created that when logging the phone calls in new tickets the agent selects the existing user and does not create a new one.

Does that hit home, or am I completely off here?

dvnkln · August 29, 2019, 11:57am

FYI
We usually got duplicate users when agents created a new ticket the “wrong” way.

While setting the customer some agents started typing the name of the customer but didn’t pick the already existing user zammad suggested to them. Instead they finished typing the name manually and just pressed return, thus creating a duplicate user.

BUT i think zammad fixed that behaviour already.

cheers

AStatler · August 29, 2019, 1:05pm

Oh! Okay, I feel embarrassed. Here’s the probably important bit of information.

This isn’t duplicate customers being created over a span of time, rather when one is made the rest are made at the same time. IE One is Customer ID 400, then we have 401 402 403 404 and 405.

MrGeneration · August 29, 2019, 5:56pm

That’s interesting.
So is this user interaction based or happening “automatically”? :x

AStatler · August 29, 2019, 6:28pm

I -believe- it’s automatically happening when an agent creates the user for the first time.
Users don’t interface with our system at all currently, just agents.

I’ve watched the agent enter a customer and don’t see anything strange, but I admittedly don’t catch the duplicate until later after it has happened. It does not happen every time.

MrGeneration · August 30, 2019, 10:46am

Possible issue might be instable connections to the server.
You should be able to see those happenings within the logfile (at least duplicate creations).

It’s also possible that it’s a combination between browser and some addon installed.
Maybe you can find differences between your agents.

AStatler · August 30, 2019, 1:53pm

Perfect, thanks. Just to verify that is the ‘Var/log/zammad/’ location and the production log?

MrGeneration · August 30, 2019, 5:25pm

Yes, that’s correct!
Unless you changed logging to Stdout, which I don’t suspect at the moment

AStatler · September 3, 2019, 2:33pm

I’ve tracked down one of the events, though I’ll be honest in that I don’t understand it enough to see if anything is wrong here. It looks like the same thing is just running twice.

The two events for customer creation are about 1.5 seconds apart.
Our network is just over a switch to the server. Does this look like some kind of a bounce?

Thanks.

I, [2019-08-26T16:27:46.598232 #8596-69848115709440]  INFO -- : Processing by UsersController#create as JSON

I, [2019-08-26T16:27:48.122554 #8596-69848115692280]  INFO -- : Processing by UsersController#create as JSON

Log block

I, [2019-08-26T16:27:34.458257 #8596-69848214619480]  INFO -- : Started PUT "/api/v1/taskbar/1084" for 192.168.0.119 at 2019-08-26 16:27:34 +0000
I, [2019-08-26T16:27:34.469663 #8596-69848214619480]  INFO -- : Processing by TaskbarController#update as JSON
I, [2019-08-26T16:27:34.469855 #8596-69848214619480]  INFO -- :   Parameters: {"key"=>"Ticket-345", "client_id"=>"123", "callback"=>"TicketZoom", "state"=>{"ticket"=>{}, "article"=>{"form_id"=>"836754793"}}, "params"=>{"ticket_id"=>"345", "shown"=>true}, "prio"=>8, "notify"=>false, "active"=>true, "attachments"=>[], "updated_at"=>"2019-08-26T16:25:32.332Z", "id"=>"1084"}
I, [2019-08-26T16:27:34.547288 #8596-69848214619480]  INFO -- : Completed 200 OK in 77ms (Views: 1.2ms | ActiveRecord: 19.1ms)
I, [2019-08-26T16:27:46.586224 #8596-69848115709440]  INFO -- : Started POST "/api/v1/users" for 192.168.0.131 at 2019-08-26 16:27:46 +0000
I, [2019-08-26T16:27:46.598232 #8596-69848115709440]  INFO -- : Processing by UsersController#create as JSON
I, [2019-08-26T16:27:46.598424 #8596-69848115709440]  INFO -- :   Parameters: {"firstname"=>"XXXXXX", "lastname"=>"XXXXXX", "email"=>"", "web"=>"", "password"=>"[FILTERED]", "phone"=>"xxx-xxx-xxxx", "fax"=>"", "mobile"=>"", "organization_id"=>"8", "department"=>"", "note"=>"", "role_ids"=>[], "group_ids"=>{"1"=>[], "2"=>[]}, "active"=>true, "address"=>"", "location"=>"", "vip"=>false, "id"=>"c-749"}
I, [2019-08-26T16:27:46.680520 #8596-69848115709440]  INFO -- : Enqueued SearchIndexJob (Job ID: 1ec92836-35b0-4fb9-afd5-4f49f3420960) to DelayedJob(default) with arguments: "User", 434
I, [2019-08-26T16:27:46.698617 #8596-69848115709440]  INFO -- : Enqueued SearchIndexJob (Job ID: 7dde9051-2f4d-4b05-8e5c-366cbdfc8ae8) to DelayedJob(default) with arguments: "Organization", 8
I, [2019-08-26T16:27:46.711966 #8596-69848115709440]  INFO -- : Enqueued SearchIndexJob (Job ID: 5173c81f-42a4-454e-a72e-75c1e3c45bc3) to DelayedJob(default) with arguments: "User", 286
I, [2019-08-26T16:27:46.722859 #8596-69848115709440]  INFO -- : Enqueued SearchIndexJob (Job ID: 7411e3bb-1795-4e86-a057-025d3175d626) to DelayedJob(default) with arguments: "User", 5
I, [2019-08-26T16:27:46.733697 #8596-69848115709440]  INFO -- : Enqueued SearchIndexJob (Job ID: 04c78f3d-e3df-4bc0-9de5-d09e7f3db8b8) to DelayedJob(default) with arguments: "User", 155
I, [2019-08-26T16:27:46.744619 #8596-69848115709440]  INFO -- : Enqueued SearchIndexJob (Job ID: 8bd84a8a-a9b8-42d2-a2d3-22ee24ec5ea6) to DelayedJob(default) with arguments: "User", 66
I, [2019-08-26T16:27:46.755437 #8596-69848115709440]  INFO -- : Enqueued SearchIndexJob (Job ID: f8e9668d-410f-46c3-8acd-f2099c175aea) to DelayedJob(default) with arguments: "User", 89
I, [2019-08-26T16:27:46.766244 #8596-69848115709440]  INFO -- : Enqueued SearchIndexJob (Job ID: 94ce7508-e997-49e8-b76c-b6156d49445c) to DelayedJob(default) with arguments: "User", 198
I, [2019-08-26T16:27:46.776458 #8596-69848115709440]  INFO -- : Enqueued SearchIndexJob (Job ID: 8c3e0a91-a57e-4f05-9fa7-107bec9d5b4f) to DelayedJob(default) with arguments: "User", 52
I, [2019-08-26T16:27:46.786963 #8596-69848115709440]  INFO -- : Enqueued SearchIndexJob (Job ID: e8bcc3d1-8817-4b32-91ec-fb7d2860bc64) to DelayedJob(default) with arguments: "User", 246
I, [2019-08-26T16:27:46.797193 #8596-69848115709440]  INFO -- : Enqueued SearchIndexJob (Job ID: 32fe9223-e755-458d-ad2d-381017c374ce) to DelayedJob(default) with arguments: "User", 152
I, [2019-08-26T16:27:46.807670 #8596-69848115709440]  INFO -- : Enqueued SearchIndexJob (Job ID: 27303e53-680f-437e-acc2-b7bc34ef6580) to DelayedJob(default) with arguments: "User", 32
I, [2019-08-26T16:27:46.818094 #8596-69848115709440]  INFO -- : Enqueued SearchIndexJob (Job ID: a49e117b-f611-4cab-9354-9eb8785ca10a) to DelayedJob(default) with arguments: "User", 64
I, [2019-08-26T16:27:46.828429 #8596-69848115709440]  INFO -- : Enqueued SearchIndexJob (Job ID: 4e10305a-33dc-4ae2-addc-bd6da4bd7dc0) to DelayedJob(default) with arguments: "User", 393
I, [2019-08-26T16:27:46.838843 #8596-69848115709440]  INFO -- : Enqueued SearchIndexJob (Job ID: 129bf717-f100-4814-a3f9-7942e220c132) to DelayedJob(default) with arguments: "User", 362
I, [2019-08-26T16:27:46.849707 #8596-69848115709440]  INFO -- : Enqueued SearchIndexJob (Job ID: 6de90968-8158-4833-bcce-0583726403a5) to DelayedJob(default) with arguments: "User", 310
I, [2019-08-26T16:27:46.859947 #8596-69848115709440]  INFO -- : Enqueued SearchIndexJob (Job ID: bfed7e10-f93e-449a-8283-9817066089cd) to DelayedJob(default) with arguments: "User", 189
I, [2019-08-26T16:27:46.870415 #8596-69848115709440]  INFO -- : Enqueued SearchIndexJob (Job ID: ae8f1552-fac4-4dcf-b60e-edc1a5a30ded) to DelayedJob(default) with arguments: "User", 291
I, [2019-08-26T16:27:46.907610 #8596-69848115709440]  INFO -- : Performing UpdateCtiLogsByCallerJob (Job ID: 3a73748f-ca40-4e45-90a7-14762264885f) from DelayedJob(default) with arguments: "1566836866981630", {:limit=>20}
I, [2019-08-26T16:27:47.075286 #8596-69848115709440]  INFO -- : Performed UpdateCtiLogsByCallerJob (Job ID: 3a73748f-ca40-4e45-90a7-14762264885f) from DelayedJob(default) in 167.44ms
I, [2019-08-26T16:27:47.098839 #8596-69848115709440]  INFO -- : Enqueued UpdateCtiLogsByCallerJob (Job ID: 4555fe9b-b15a-4ab8-b515-63e899f14852) to DelayedJob(default) with arguments: "1566836866981630", {:limit=>40, :offset=>20}
I, [2019-08-26T16:27:47.113788 #8596-69848115709440]  INFO -- : Performing UpdateCtiLogsByCallerJob (Job ID: f50a28e3-e9e0-4525-aae9-c2b50b6ab3eb) from DelayedJob(default) with arguments: "5098212699", {:limit=>20}
I, [2019-08-26T16:27:47.117667 #8596-69848115709440]  INFO -- : Performed UpdateCtiLogsByCallerJob (Job ID: f50a28e3-e9e0-4525-aae9-c2b50b6ab3eb) from DelayedJob(default) in 3.75ms
I, [2019-08-26T16:27:47.140454 #8596-69848115709440]  INFO -- : Enqueued UpdateCtiLogsByCallerJob (Job ID: 367a696d-a45a-4cc0-b552-ec622a95b39c) to DelayedJob(default) with arguments: "5098212699", {:limit=>40, :offset=>20}
I, [2019-08-26T16:27:47.204332 #8596-69848115709440]  INFO -- : Completed 201 Created in 606ms (Views: 0.8ms | ActiveRecord: 170.5ms)
I, [2019-08-26T16:27:47.224802 #8596-69848220920760]  INFO -- : Started GET "/api/v1/users/434?full=true&_=1566824998114" for 192.168.0.131 at 2019-08-26 16:27:47 +0000
I, [2019-08-26T16:27:47.231100 #8596-69848220920760]  INFO -- : Processing by UsersController#show as JSON
I, [2019-08-26T16:27:47.231219 #8596-69848220920760]  INFO -- :   Parameters: {"full"=>"true", "_"=>"1566824998114", "id"=>"434"}
I, [2019-08-26T16:27:47.742610 #8596-69848220920760]  INFO -- : Completed 200 OK in 511ms (Views: 13.3ms | ActiveRecord: 90.6ms)
I, [2019-08-26T16:27:47.822602 #8596-69848122310480]  INFO -- : Started GET "/api/v1/ticket_customer?customer_id=198&_=1566824998115" for 192.168.0.131 at 2019-08-26 16:27:47 +0000
I, [2019-08-26T16:27:47.828263 #8596-69848220895880]  INFO -- : Started GET "/api/v1/ticket_customer?customer_id=198&_=1566824998116" for 192.168.0.131 at 2019-08-26 16:27:47 +0000
I, [2019-08-26T16:27:47.835935 #8596-69848122310480]  INFO -- : Processing by TicketsController#ticket_customer as JSON
I, [2019-08-26T16:27:47.836110 #8596-69848122310480]  INFO -- :   Parameters: {"customer_id"=>"198", "_"=>"1566824998115"}
I, [2019-08-26T16:27:47.839151 #8596-69848115709440]  INFO -- : Started GET "/api/v1/ticket_customer?customer_id=393&_=1566824998117" for 192.168.0.131 at 2019-08-26 16:27:47 +0000
I, [2019-08-26T16:27:47.846744 #8596-69848220895880]  INFO -- : Processing by TicketsController#ticket_customer as JSON
I, [2019-08-26T16:27:47.846920 #8596-69848220895880]  INFO -- :   Parameters: {"customer_id"=>"198", "_"=>"1566824998116"}
I, [2019-08-26T16:27:47.848270 #8596-69848214619480]  INFO -- : Started GET "/api/v1/ticket_customer?customer_id=393&_=1566824998118" for 192.168.0.131 at 2019-08-26 16:27:47 +0000
I, [2019-08-26T16:27:47.865638 #8596-69848115709440]  INFO -- : Processing by TicketsController#ticket_customer as JSON
I, [2019-08-26T16:27:47.875111 #8596-69848115709440]  INFO -- :   Parameters: {"customer_id"=>"393", "_"=>"1566824998117"}
I, [2019-08-26T16:27:47.866649 #8596-69848220920760]  INFO -- : Started GET "/api/v1/templates/?full=true&_=1566824998119" for 192.168.0.131 at 2019-08-26 16:27:47 +0000
I, [2019-08-26T16:27:47.877289 #8596-69848115692280]  INFO -- : Started GET "/api/v1/ticket_customer?customer_id=434&_=1566824998120" for 192.168.0.131 at 2019-08-26 16:27:47 +0000
I, [2019-08-26T16:27:47.904358 #8596-69848220920760]  INFO -- : Processing by TemplatesController#index as JSON
I, [2019-08-26T16:27:47.904534 #8596-69848220920760]  INFO -- :   Parameters: {"full"=>"true", "_"=>"1566824998119"}
I, [2019-08-26T16:27:47.870140 #8596-69848214619480]  INFO -- : Processing by TicketsController#ticket_customer as JSON
I, [2019-08-26T16:27:47.910960 #8596-69848214619480]  INFO -- :   Parameters: {"customer_id"=>"393", "_"=>"1566824998118"}
I, [2019-08-26T16:27:47.958258 #8596-69848115692280]  INFO -- : Processing by TicketsController#ticket_customer as JSON
I, [2019-08-26T16:27:47.958445 #8596-69848115692280]  INFO -- :   Parameters: {"customer_id"=>"434", "_"=>"1566824998120"}
I, [2019-08-26T16:27:48.018682 #8596-69848220920760]  INFO -- : Completed 200 OK in 114ms (Views: 0.4ms | ActiveRecord: 57.6ms)
I, [2019-08-26T16:27:48.044650 #8596-69848115692280]  INFO -- : Completed 200 OK in 80ms (Views: 0.5ms | ActiveRecord: 34.5ms)
I, [2019-08-26T16:27:48.048165 #8596-69848220920760]  INFO -- : Started GET "/api/v1/ticket_customer?customer_id=434&_=1566824998121" for 192.168.0.131 at 2019-08-26 16:27:48 +0000
I, [2019-08-26T16:27:48.065775 #8596-69848220920760]  INFO -- : Processing by TicketsController#ticket_customer as JSON
I, [2019-08-26T16:27:48.065947 #8596-69848220920760]  INFO -- :   Parameters: {"customer_id"=>"434", "_"=>"1566824998121"}
I, [2019-08-26T16:27:48.105645 #8596-69848115692280]  INFO -- : Started POST "/api/v1/users" for 192.168.0.131 at 2019-08-26 16:27:48 +0000
I, [2019-08-26T16:27:48.122554 #8596-69848115692280]  INFO -- : Processing by UsersController#create as JSON
I, [2019-08-26T16:27:48.122819 #8596-69848115692280]  INFO -- :   Parameters: {"firstname"=>"XXXXXX", "lastname"=>"XXXXXX", "email"=>"", "web"=>"", "password"=>"[FILTERED]", "phone"=>"xxx-xxx-xxxx", "fax"=>"", "mobile"=>"", "organization_id"=>"8", "department"=>"", "note"=>"", "role_ids"=>[], "group_ids"=>{"1"=>[], "2"=>[]}, "active"=>true, "address"=>"", "location"=>"", "vip"=>false, "id"=>"c-768"}
I, [2019-08-26T16:27:48.129089 #8596-69848220920760]  INFO -- : Completed 200 OK in 63ms (Views: 0.3ms | ActiveRecord: 31.6ms)
I, [2019-08-26T16:27:48.390068 #8596-69848115709440]  INFO -- : Completed 200 OK in 512ms (Views: 46.8ms | ActiveRecord: 81.8ms)
I, [2019-08-26T16:27:48.422565 #8596-69848220895880]  INFO -- : Completed 200 OK in 575ms (Views: 23.7ms | ActiveRecord: 93.6ms)
I, [2019-08-26T16:27:48.429348 #8596-69848214619480]  INFO -- : Completed 200 OK in 510ms (Views: 20.7ms | ActiveRecord: 79.7ms)
I, [2019-08-26T16:27:48.432017 #8596-69848115692280]  INFO -- : Enqueued SearchIndexJob (Job ID: b251531a-770a-45bc-9443-70ff9f11f647) to DelayedJob(default) with arguments: "User", 435
I, [2019-08-26T16:27:48.460421 #8596-69848122310480]  INFO -- : Completed 200 OK in 624ms (Views: 19.0ms | ActiveRecord: 84.6ms)
I, [2019-08-26T16:27:48.479492 #8596-69848115692280]  INFO -- : Enqueued SearchIndexJob (Job ID: a7372c92-a008-464c-b556-753ebd1272a5) to DelayedJob(default) with arguments: "Organization", 8
I, [2019-08-26T16:27:48.491318 #8596-69848115692280]  INFO -- : Enqueued SearchIndexJob (Job ID: 4fe25e74-e941-495e-ac82-fa4a9b9a4a03) to DelayedJob(default) with arguments: "User", 286
I, [2019-08-26T16:27:48.500874 #8596-69848115692280]  INFO -- : Enqueued SearchIndexJob (Job ID: 06a45198-3afa-4275-a267-1d722e1b0402) to DelayedJob(default) with arguments: "User", 5
I, [2019-08-26T16:27:48.510375 #8596-69848115692280]  INFO -- : Enqueued SearchIndexJob (Job ID: 9c4e0810-cf7c-4eb7-9369-f85485ff9bc1) to DelayedJob(default) with arguments: "User", 155
I, [2019-08-26T16:27:48.519821 #8596-69848115692280]  INFO -- : Enqueued SearchIndexJob (Job ID: c2b8309c-a7b3-4ded-a57f-d8f5c4cc5979) to DelayedJob(default) with arguments: "User", 66
I, [2019-08-26T16:27:48.529176 #8596-69848115692280]  INFO -- : Enqueued SearchIndexJob (Job ID: cca284cd-dbea-47dc-abe1-854cdd02dff5) to DelayedJob(default) with arguments: "User", 89
I, [2019-08-26T16:27:48.538823 #8596-69848115692280]  INFO -- : Enqueued SearchIndexJob (Job ID: 9df1b6c6-6e4e-451c-a4ee-cd6f2b879e05) to DelayedJob(default) with arguments: "User", 198
I, [2019-08-26T16:27:48.548299 #8596-69848115692280]  INFO -- : Enqueued SearchIndexJob (Job ID: 9b5940ef-218b-4a0f-9dcc-d4d89c29ca10) to DelayedJob(default) with arguments: "User", 52
I, [2019-08-26T16:27:48.557780 #8596-69848115692280]  INFO -- : Enqueued SearchIndexJob (Job ID: dbad5b77-88db-4027-9288-cb0ff6935729) to DelayedJob(default) with arguments: "User", 246
I, [2019-08-26T16:27:48.567286 #8596-69848115692280]  INFO -- : Enqueued SearchIndexJob (Job ID: 51627b8f-0293-4703-a0c7-8f9ea44fde97) to DelayedJob(default) with arguments: "User", 152
I, [2019-08-26T16:27:48.576888 #8596-69848115692280]  INFO -- : Enqueued SearchIndexJob (Job ID: 6085b23d-71b6-4037-8d60-931932fb0434) to DelayedJob(default) with arguments: "User", 32
I, [2019-08-26T16:27:48.586375 #8596-69848115692280]  INFO -- : Enqueued SearchIndexJob (Job ID: 3845260a-eeb3-45ab-baf3-30735430bfab) to DelayedJob(default) with arguments: "User", 64
I, [2019-08-26T16:27:48.595790 #8596-69848115692280]  INFO -- : Enqueued SearchIndexJob (Job ID: 7511193f-9a8a-45ef-be9c-d6eaf8630443) to DelayedJob(default) with arguments: "User", 393
I, [2019-08-26T16:27:48.605124 #8596-69848115692280]  INFO -- : Enqueued SearchIndexJob (Job ID: 21ce8f27-0366-4420-965f-5bd7482c3ea8) to DelayedJob(default) with arguments: "User", 362
I, [2019-08-26T16:27:48.614625 #8596-69848115692280]  INFO -- : Enqueued SearchIndexJob (Job ID: 3d78bb02-f5cd-4387-893f-4ea52d276783) to DelayedJob(default) with arguments: "User", 310
I, [2019-08-26T16:27:48.624292 #8596-69848115692280]  INFO -- : Enqueued SearchIndexJob (Job ID: e6b85c8c-23f7-4362-aa9d-4f9c9753e578) to DelayedJob(default) with arguments: "User", 189
I, [2019-08-26T16:27:48.634056 #8596-69848115692280]  INFO -- : Enqueued SearchIndexJob (Job ID: e5a15375-94d1-43d7-8256-960f21e9fb2d) to DelayedJob(default) with arguments: "User", 291
I, [2019-08-26T16:27:48.643809 #8596-69848115692280]  INFO -- : Enqueued SearchIndexJob (Job ID: e4b78d21-badc-437c-a5a0-27f8b592772b) to DelayedJob(default) with arguments: "User", 434
I, [2019-08-26T16:27:48.682566 #8596-69848115692280]  INFO -- : Performing UpdateCtiLogsByCallerJob (Job ID: e966e087-08e4-4307-af63-418c0ba51dae) from DelayedJob(default) with arguments: "1566836868471307", {:limit=>20}
I, [2019-08-26T16:27:48.692928 #8596-69848115692280]  INFO -- : Performed UpdateCtiLogsByCallerJob (Job ID: e966e087-08e4-4307-af63-418c0ba51dae) from DelayedJob(default) in 10.13ms
I, [2019-08-26T16:27:48.715614 #8596-69848115692280]  INFO -- : Enqueued UpdateCtiLogsByCallerJob (Job ID: f2e2bd1f-43c2-4de4-9f29-a3aa8fb95552) to DelayedJob(default) with arguments: "1566836868471307", {:limit=>40, :offset=>20}
I, [2019-08-26T16:27:48.732490 #8596-69848115692280]  INFO -- : Performing UpdateCtiLogsByCallerJob (Job ID: da2e480c-a745-4c5d-8e41-9f8522412725) from DelayedJob(default) with arguments: "5098212699", {:limit=>20}
I, [2019-08-26T16:27:48.740878 #8596-69848115692280]  INFO -- : Performed UpdateCtiLogsByCallerJob (Job ID: da2e480c-a745-4c5d-8e41-9f8522412725) from DelayedJob(default) in 8.15ms
I, [2019-08-26T16:27:48.765580 #8596-69848115692280]  INFO -- : Enqueued UpdateCtiLogsByCallerJob (Job ID: 9da71cd1-fe26-4f28-a587-328b764607e0) to DelayedJob(default) with arguments: "5098212699", {:limit=>40, :offset=>20}
I, [2019-08-26T16:27:48.857571 #8596-69848115692280]  INFO -- : Completed 201 Created in 734ms (Views: 1.1ms | ActiveRecord: 330.2ms)
I, [2019-08-26T16:27:48.876371 #8596-69848220920760]  INFO -- : Started GET "/api/v1/users/435?full=true&_=1566824998122" for 192.168.0.131 at 2019-08-26 16:27:48 +0000
I, [2019-08-26T16:27:48.885497 #8596-69848220920760]  INFO -- : Processing by UsersController#show as JSON
I, [2019-08-26T16:27:48.885639 #8596-69848220920760]  INFO -- :   Parameters: {"full"=>"true", "_"=>"1566824998122", "id"=>"435"}
I, [2019-08-26T16:27:49.459296 #8596-69848220920760]  INFO -- : Completed 200 OK in 574ms (Views: 7.6ms | ActiveRecord: 97.3ms)
I, [2019-08-26T16:27:49.518061 #8596-69848115709440]  INFO -- : Started GET "/api/v1/ticket_customer?customer_id=198&_=1566824998123" for 192.168.0.131 at 2019-08-26 16:27:49 +0000
I, [2019-08-26T16:27:49.523204 #8596-69848214619480]  INFO -- : Started GET "/api/v1/ticket_customer?customer_id=198&_=1566824998124" for 192.168.0.131 at 2019-08-26 16:27:49 +0000
I, [2019-08-26T16:27:49.528741 #8596-69848115709440]  INFO -- : Processing by TicketsController#ticket_customer as JSON
I, [2019-08-26T16:27:49.528829 #8596-69848115709440]  INFO -- :   Parameters: {"customer_id"=>"198", "_"=>"1566824998123"}
I, [2019-08-26T16:27:49.533075 #8596-69848214619480]  INFO -- : Processing by TicketsController#ticket_customer as JSON
I, [2019-08-26T16:27:49.533212 #8596-69848214619480]  INFO -- :   Parameters: {"customer_id"=>"198", "_"=>"1566824998124"}
I, [2019-08-26T16:27:49.536490 #8596-69848122310480]  INFO -- : Started GET "/api/v1/ticket_customer?customer_id=393&_=1566824998125" for 192.168.0.131 at 2019-08-26 16:27:49 +0000
I, [2019-08-26T16:27:49.540949 #8596-69848220895880]  INFO -- : Started GET "/api/v1/ticket_customer?customer_id=434&_=1566824998127" for 192.168.0.131 at 2019-08-26 16:27:49 +0000
I, [2019-08-26T16:27:49.550165 #8596-69848115692280]  INFO -- : Started GET "/api/v1/ticket_customer?customer_id=393&_=1566824998126" for 192.168.0.131 at 2019-08-26 16:27:49 +0000
I, [2019-08-26T16:27:49.557922 #8596-69848220895880]  INFO -- : Processing by TicketsController#ticket_customer as JSON
I, [2019-08-26T16:27:49.558099 #8596-69848220895880]  INFO -- :   Parameters: {"customer_id"=>"434", "_"=>"1566824998127"}
I, [2019-08-26T16:27:49.564064 #8596-69848122310480]  INFO -- : Processing by TicketsController#ticket_customer as JSON
I, [2019-08-26T16:27:49.564240 #8596-69848122310480]  INFO -- :   Parameters: {"customer_id"=>"393", "_"=>"1566824998125"}
I, [2019-08-26T16:27:49.593591 #8596-69848115692280]  INFO -- : Processing by TicketsController#ticket_customer as JSON
I, [2019-08-26T16:27:49.593769 #8596-69848115692280]  INFO -- :   Parameters: {"customer_id"=>"393", "_"=>"1566824998126"}
I, [2019-08-26T16:27:49.608356 #8596-69848220920760]  INFO -- : Started GET "/api/v1/templates/?full=true&_=1566824998128" for 192.168.0.131 at 2019-08-26 16:27:49 +0000
I, [2019-08-26T16:27:49.639497 #8596-69848220920760]  INFO -- : Processing by TemplatesController#index as JSON
I, [2019-08-26T16:27:49.639676 #8596-69848220920760]  INFO -- :   Parameters: {"full"=>"true", "_"=>"1566824998128"}
I, [2019-08-26T16:27:49.648610 #8596-69848220895880]  INFO -- : Completed 200 OK in 90ms (Views: 0.4ms | ActiveRecord: 62.1ms)
I, [2019-08-26T16:27:49.695542 #8596-69848220895880]  INFO -- : Started GET "/api/v1/ticket_customer?customer_id=435&_=1566824998130" for 192.168.0.131 at 2019-08-26 16:27:49 +0000
I, [2019-08-26T16:27:49.707074 #8596-69848220895880]  INFO -- : Processing by TicketsController#ticket_customer as JSON
I, [2019-08-26T16:27:49.707249 #8596-69848220895880]  INFO -- :   Parameters: {"customer_id"=>"435", "_"=>"1566824998130"}
I, [2019-08-26T16:27:49.933632 #8596-69848220920760]  INFO -- : Completed 200 OK in 294ms (Views: 0.2ms | ActiveRecord: 233.5ms)
I, [2019-08-26T16:27:49.949543 #8589-47386118006140]  INFO -- : 2019-08-26T16:27:49+0000: [Worker(host:zammad pid:8589)] Job SearchIndexJob [1ec92836-35b0-4fb9-afd5-4f49f3420960] from DelayedJob(default) with arguments: ["User", 434] (id=44364) (queue=default) RUNNING
I, [2019-08-26T16:27:49.950586 #8596-69848220895880]  INFO -- : Completed 200 OK in 243ms (Views: 0.2ms | ActiveRecord: 19.9ms)
I, [2019-08-26T16:27:50.053321 #8596-69848115709440]  INFO -- : Completed 200 OK in 524ms (Views: 28.6ms | ActiveRecord: 76.5ms)
I, [2019-08-26T16:27:50.068099 #8596-69848122310480]  INFO -- : Completed 200 OK in 504ms (Views: 42.0ms | ActiveRecord: 66.8ms)
I, [2019-08-26T16:27:50.076167 #8589-47386038830580]  INFO -- : Scheduler running...
I, [2019-08-26T16:27:50.096072 #8596-69848214619480]  INFO -- : Completed 200 OK in 563ms (Views: 17.1ms | ActiveRecord: 84.7ms)
I, [2019-08-26T16:27:50.098798 #8589-47386118006140]  INFO -- : Performing SearchIndexJob (Job ID: 1ec92836-35b0-4fb9-afd5-4f49f3420960) from DelayedJob(default) with arguments: "User", 434

MrGeneration · September 3, 2019, 4:14pm

Well that’s odd and really shouldn’t happen…

Does your chrome have any addons installed?
Is it happening on the same machine permanently? (Trying to find differences from “normal” setups here that might help us reproduce this)

Also, could you please share information about your server?

is this a physical machine or a virtual machine?
what cpu is being used (if virtual also tell us how many cores it does have)
how much RAM does the machine have?
what’s the storage of the host? (SSD/HDD/SAS/…)

Is the overall performance of your host good? What’s the average load? (uptime can tell you that, just like top or htop )

AStatler · September 3, 2019, 4:31pm

I’m just glad I’m not crazy.

Intermittent issues are the worst. Thanks for taking your time on this weird one.

This happens on two different machines, I’ve found duplicates I apparently created too! Both using chrome. One has google docs extension, the other has google docs as well as a dark mode theme.

The server is a virtual machine on a proxmox set up.
1 socket, 4 cores allocated to zammad
10 gigs of ram, with it holding steady at just under 8 used.
Memory usage 72.38% (7.24 GiB of 10.00 GiB)
Storage is just a set of 2 TB HDD, zammad is allocated 250 GB.

On the VM that hosts Zammad
uptime: 16:26:02 up 12 days, 20:04, 1 user, load average: 0.02, 0.04, 0.08
top: 16:26:48 up 12 days, 20:04, 1 user, load average: 0.01, 0.03, 0.08

AStatler · September 3, 2019, 4:31pm

Would additional logs of the duplication events be helpful?

MrGeneration · September 3, 2019, 4:35pm

What duplication events do you mean?
You mean the time where it duplicates entries? No I think it’s coming from your Browser.

Maybe take a look into your webserver logifles if it maybe sends some 5xx error that might make the WebApp to think it needs to resend (while the response is just too slow).

Could you try reproduce this issue with a clean chrome without any addons?
I don’t see why it should happen with those addons, but it’s worth a try ;x

AStatler · September 3, 2019, 4:38pm

Got it, having my coworker also clear off all extensions.
It doesn’t happen every time, but I’ll see if this helps.
They’d be a small loss for solving this =)

Apologies, where would I find those logfiles for the webserver?

MrGeneration · September 3, 2019, 4:45pm

Either in /var/log/nginx/{zammad.access.log} and /var/log/nginx/{zammad.error.log}
or somewhere in /var/log/apache2/ depending on the webserver being used.

By default that would be nginx.

AStatler · September 6, 2019, 4:07pm

Ah good. Yes, I had looked through that one.

Apologies for the delay, I’ve looked through the webserver logs.
I believe these are the time stamps that correspond with the previous creation logs.

Appreciate the help, this has been rather a crash course of learning getting everything set up here.

More below, but does this look like the double send from a browser that would create the customer twice?

192.168.0.131 - - [26/Aug/2019:16:27:49 +0000] “GET /api/v1/ticket_customer?customer_id=434&=1566824998127 HTTP/1.1" 499 0 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:49 +0000] "GET /api/v1/ticket_customer?customer_id=435&=1566824998129 HTTP/1.1” 499 0 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”

webserver log

192.168.0.131 - - [26/Aug/2019:16:27:47 +0000] “POST /api/v1/users HTTP/1.1” 201 740 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:47 +0000] “GET /api/v1/users/434?full=true&=1566824998114 HTTP/1.1" 200 3123 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:48 +0000] "GET /api/v1/templates/?full=true&=1566824998119 HTTP/1.1” 200 58 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:48 +0000] “GET /api/v1/ticket_customer?customer_id=434&=1566824998120 HTTP/1.1" 200 74 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:48 +0000] "GET /api/v1/ticket_customer?customer_id=434&=1566824998121 HTTP/1.1” 200 74 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:48 +0000] “GET /api/v1/ticket_customer?customer_id=393&=1566824998117 HTTP/1.1" 200 3810 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:48 +0000] "GET /api/v1/ticket_customer?customer_id=198&=1566824998116 HTTP/1.1” 200 4121 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:48 +0000] “GET /api/v1/ticket_customer?customer_id=393&=1566824998118 HTTP/1.1" 200 3810 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:48 +0000] "GET /api/v1/ticket_customer?customer_id=198&=1566824998115 HTTP/1.1” 200 4121 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:48 +0000] “POST /api/v1/users HTTP/1.1” 201 740 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:49 +0000] “GET /api/v1/users/435?full=true&=1566824998122 HTTP/1.1" 200 3195 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:49 +0000] "GET /api/v1/ticket_customer?customer_id=434&=1566824998127 HTTP/1.1” 499 0 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:49 +0000] “GET /api/v1/ticket_customer?customer_id=435&=1566824998129 HTTP/1.1" 499 0 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:49 +0000] "GET /api/v1/templates/?full=true&=1566824998128 HTTP/1.1” 200 58 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:49 +0000] “GET /api/v1/ticket_customer?customer_id=435&=1566824998130 HTTP/1.1" 200 74 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:50 +0000] "GET /api/v1/ticket_customer?customer_id=198&=1566824998123 HTTP/1.1” 200 4165 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:50 +0000] “GET /api/v1/ticket_customer?customer_id=393&=1566824998125 HTTP/1.1" 200 3890 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:50 +0000] "GET /api/v1/ticket_customer?customer_id=198&=1566824998124 HTTP/1.1” 200 4165 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:50 +0000] “GET /api/v1/ticket_customer?customer_id=393&=1566824998126 HTTP/1.1" 200 3890 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.119 - - [26/Aug/2019:16:27:50 +0000] "GET /api/v1/ticket_customer?customer_id=408&=1566832267297 HTTP/1.1” 200 2175 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.119 - - [26/Aug/2019:16:27:50 +0000] “PUT /api/v1/users/408 HTTP/1.1” 200 474 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.119 - - [26/Aug/2019:16:27:50 +0000] “GET /api/v1/ticket_customer?customer_id=408&=1566832267298 HTTP/1.1" 200 2190 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:27:52 +0000] “PUT /api/v1/taskbar/1086 HTTP/1.1” 200 466 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:28:07 +0000] “PUT /api/v1/taskbar/1086 HTTP/1.1” 200 471 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:28:11 +0000] “PUT /api/v1/taskbar/1086 HTTP/1.1” 200 479 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:28:15 +0000] “PUT /api/v1/taskbar/1086 HTTP/1.1” 200 491 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:28:19 +0000] "GET /api/v1/search/user-organization?query=Judy+Forbes&=1566824998131 HTTP/1.1” 200 3196 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:28:22 +0000] “PUT /api/v1/taskbar/1086 HTTP/1.1” 200 511 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:28:27 +0000] “PUT /api/v1/taskbar/1086 HTTP/1.1” 200 532 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:28:32 +0000] “PUT /api/v1/taskbar/1086 HTTP/1.1” 200 542 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:28:37 +0000] “PUT /api/v1/taskbar/1086 HTTP/1.1” 200 567 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:28:39 +0000] “PUT /api/v1/taskbar/1086 HTTP/1.1” 200 574 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:28:41 +0000] “PUT /api/v1/taskbar/1086 HTTP/1.1” 200 578 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:28:44 +0000] “PUT /api/v1/taskbar/1086 HTTP/1.1” 200 588 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:28:48 +0000] “PUT /api/v1/taskbar/1086 HTTP/1.1” 200 588 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:28:51 +0000] “PUT /api/v1/taskbar/1086 HTTP/1.1” 200 589 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:02 +0000] “PUT /api/v1/taskbar/1086 HTTP/1.1” 200 599 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:05 +0000] “PUT /api/v1/taskbar/1086 HTTP/1.1” 200 601 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:06 +0000] “GET /api/v1/tag_search?term=education HTTP/1.1” 200 62 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:08 +0000] “POST /api/v1/tickets HTTP/1.1” 201 1203 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:08 +0000] “DELETE /api/v1/taskbar/1086 HTTP/1.1” 200 33 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:08 +0000] “POST /api/v1/taskbar HTTP/1.1” 201 426 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:09 +0000] “GET /api/v1/organizations/8?full=true&=1566824998134 HTTP/1.1" 200 3220 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:09 +0000] "GET /api/v1/users/435?full=true&=1566824998133 HTTP/1.1” 200 3201 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:09 +0000] “GET /api/v1/tickets/387?all=true&=1566824998132 HTTP/1.1" 499 0 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:10 +0000] "GET /api/v1/tickets/387?all=true&=1566824998135 HTTP/1.1” 200 26842 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:10 +0000] “POST /api/v1/recent_view HTTP/1.1” 200 47 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:10 +0000] “GET /api/v1/ticket_customer?customer_id=435&=1566824998136 HTTP/1.1" 200 3610 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:15 +0000] "GET /api/v1/users/434?full=true&=1566824998142 HTTP/1.1” 200 3196 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:15 +0000] “GET /api/v1/users/198?full=true&=1566824998140 HTTP/1.1" 200 3154 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:15 +0000] "GET /api/v1/organizations/8?full=true&=1566824998139 HTTP/1.1” 200 3199 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:15 +0000] “GET /api/v1/users/393?full=true&=1566824998141 HTTP/1.1" 200 3186 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:15 +0000] "GET /api/v1/users/435?full=true&=1566824998138 HTTP/1.1” 200 3193 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:15 +0000] “PUT /api/v1/taskbar/1087 HTTP/1.1” 200 279 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:16 +0000] “GET /api/v1/ticket_customer?customer_id=198&=1566824998143 HTTP/1.1" 200 4179 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:16 +0000] "GET /api/v1/ticket_customer?customer_id=198&=1566824998144 HTTP/1.1” 200 4179 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:16 +0000] “GET /api/v1/ticket_customer?customer_id=393&=1566824998145 HTTP/1.1" 200 3894 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:16 +0000] "GET /api/v1/ticket_customer?customer_id=393&=1566824998146 HTTP/1.1” 200 3894 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:16 +0000] “GET /api/v1/ticket_customer?customer_id=435&=1566824998147 HTTP/1.1" 200 3597 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:29:17 +0000] "GET /api/v1/recent_view/?full=true&=1566824998137 HTTP/1.1” 200 18291 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.119 - - [26/Aug/2019:16:29:17 +0000] “GET /api/v1/online_notifications/?full=true&=1566832267299 HTTP/1.1" 200 20372 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”
192.168.0.131 - - [26/Aug/2019:16:31:49 +0000] "GET /api/v1/tickets/380?all=true&=1566824998148 HTTP/1.1” 200 26751 “http://192.168.0.115/” “Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36”

MrGeneration · September 6, 2019, 4:20pm

Yes, looks like your client sends the request twice.
There’s nothing inside your error log around that time? Maybe something like gateway timeout?