Error 500 when one user logs in

Technical assistance
1
  • Used Zammad version: Version 5.3.1-1672769502.c29df3bd.xenial
  • Used Zammad installation type: package
  • Operating system: Ubuntu
  • Browser + version: Firefox 114.01 64bit

Expected behavior:

Log in

Actual behavior:

We’ve got about 2000 users, lots of them are actual working fine. Only one user (agent) can’t log in. There is an internal server error (500). When I (admin) try to change something at the user file (password, status,…) the call expires and the error 500 is shown.

We’ve got a mysql (8) databse and are working behind a nginx reverse proxy.

The system ist working fine beside this problem, the user table in mysql is ok. The user worked without changes for 2 years before but returns back after absence. Absence message ended yesterday.

production.log:
E, [2023-06-15T10:22:32.830157 #3168-2270500] ERROR – : execution expired (Timeout::Error)
lib/transaction_dispatcher.rb:204:in before_update' app/models/user.rb:628:in update_last_login’
lib/auth.rb:40:in valid?' app/controllers/sessions_controller.rb:226:in authenticate_with_password’
app/controllers/sessions_controller.rb:10:in create' app/controllers/application_controller/has_download.rb:21:in block (4 levels) in module:HasDownload’
app/controllers/application_controller/has_download.rb:20:in block (3 levels) in <module:HasDownload>' app/controllers/application_controller/has_download.rb:19:in block (2 levels) in module:HasDownload’
app/controllers/application_controller/handles_transitions.rb:16:in `handle_transaction’
E, [2023-06-15T10:22:32.833010 #3168-2270500] ERROR – : Error ID c-oOsesB: execution expired
I, [2023-06-15T10:22:32.833410 #3168-2270500] INFO – : Completed 500 Internal Server Error in 5222ms (Views: 0.2ms | ActiveRecord: 13.7ms | Allocations: 27447)

Steps to reproduce the behavior:

  • Log in, change user file.
2

Hi @AchMol, please, update your Zammad installation. 5.3.1 is outdated for quite a while now and does not even get any security fixes anymore.

After the update, please verify if the same behavior still occurs. If yes, let’s see what we can do then. :slight_smile:

3

OK, thank you fliebe92, I wil try that and see what happens.

4

Hi all,

now I changed to 5.4.1 because this is the version I plan to change the database from mysql to postgres and switch to docker-compose which is 5.4.1 at the moment.

The error is the same as described above. What can we do?

5

Please provide another log excerpt that is up-to-date. :slight_smile:

6 
I, [2023-06-16T12:11:10.755219#12860-3394860]  INFO -- : Completed 200 OK in 664ms (Views: 23.0ms | ActiveRecord: 87.3ms | Allocations: 212628)
I, [2023-06-16T12:11:10.839732#12860-7590040]  INFO -- : Started PUT "/api/v1/taskbar/505215" for 10.6.1.12 at 2023-06-16 12:11:10 +0200
I, [2023-06-16T12:11:11.003776#12878-2425460]  INFO -- : Started POST "/api/v1/integration/smime" for 10.6.1.12 at 2023-06-16 12:11:11 +0200
E, [2023-06-16T12:11:11.178199#12834-4980860] ERROR -- : execution expired (Timeout::Error)
lib/transaction_dispatcher.rb:204:in `before_update'
lib/auth/user.rb:29:in `increase_login_failed'
lib/auth.rb:35:in `block in valid?'
lib/auth.rb:31:in `valid?'
app/controllers/sessions_controller.rb:234:in `authenticate_with_password'
app/controllers/sessions_controller.rb:28:in `create'
app/controllers/application_controller/has_download.rb:21:in `block (4 levels) in <module:HasDownload>'
app/controllers/application_controller/has_download.rb:20:in `block (3 levels) in <module:HasDownload>'
app/controllers/application_controller/has_download.rb:19:in `block (2 levels) in <module:HasDownload>'
app/controllers/application_controller/handles_transitions.rb:16:in `handle_transaction'
I, [2023-06-16T12:11:11.180546#12890-4505560]  INFO -- : Started GET "/api/v1/tickets/39473?full=true&_=1686895133063" for 10.6.1.12 at 2023-06-16 12:11:11 +0200
E, [2023-06-16T12:11:11.181357#12834-4980860] ERROR -- : Error ID binX_p-7: execution expired
I, [2023-06-16T12:11:11.181710#12834-4980860]  INFO -- : Completed 500 Internal Server Error in 5259ms (Views: 0.2ms | ActiveRecord: 12.3ms | Allocations: 291855)
I, [2023-06-16T12:11:11.186872#12878-2425460]  INFO -- : Processing by Integration::SMIMEController#search as JSON
7 
I, [2023-06-16T12:18:52.398279#12598-111880]  INFO -- : 2023-06-16T12:18:52+0200: [Worker(host:laemdmzweb2 pid:12598)] Job UserDeviceLogJob [90a8095f-be86-4b4e-9444-5ef573e7c0a4] from DelayedJob(default) with arguments: ["Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:109.0) Gecko/20100101 Firefox/114.0", "10.6.1.12", 30, "1303150249", "session"] (id=7501202) (queue=default) COMPLETED after 0.0835
I, [2023-06-16T12:18:52.427489#12598-111880]  INFO -- : 2023-06-16T12:18:52+0200: [Worker(host:laemdmzweb2 pid:12598)] Job UserDeviceLogJob [7e8b3c6e-dbce-484c-a3c5-d62f72964d37] from DelayedJob(default) with arguments: ["Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:109.0) Gecko/20100101 Firefox/114.0", "10.6.1.12", 30, "1303150249", "session"] (id=7501203) (queue=default) RUNNING
I, [2023-06-16T12:18:52.506464#12598-111880]  INFO -- : 2023-06-16T12:18:52+0200: [Worker(host:laemdmzweb2 pid:12598)] Job UserDeviceLogJob [7e8b3c6e-dbce-484c-a3c5-d62f72964d37] from DelayedJob(default) with arguments: ["Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:109.0) Gecko/20100101 Firefox/114.0", "10.6.1.12", 30, "1303150249", "session"] (id=7501203) (queue=default) COMPLETED after 0.0789
E, [2023-06-16T12:18:52.753707#12840-4052320] ERROR -- : execution expired (Timeout::Error)
lib/transaction_dispatcher.rb:204:in `before_update'
app/controllers/users_controller.rb:124:in `block in update'
app/controllers/users_controller.rb:120:in `update'
app/controllers/application_controller/has_download.rb:21:in `block (4 levels) in <module:HasDownload>'
app/controllers/application_controller/has_download.rb:20:in `block (3 levels) in <module:HasDownload>'
app/controllers/application_controller/has_download.rb:19:in `block (2 levels) in <module:HasDownload>'
app/controllers/application_controller/handles_transitions.rb:16:in `handle_transaction'
I, [2023-06-16T12:18:52.758995#12840-4052320]  INFO -- : Completed 500 Internal Server Error in 5258ms (Views: 0.2ms | ActiveRecord: 21.2ms | Allocations: 21363)
I, [2023-06-16T12:18:52.806830#12836-6813060]  INFO -- : Started GET "/api/v1/users/3051" for 10.6.1.12 at 2023-06-16 12:18:52 +0200
I, [2023-06-16T12:18:52.813884#12836-6813060]  INFO -- : Processing by UsersController#show as JSON
I, [2023-06-16T12:18:52.813954#12836-6813060]  INFO -- :   Parameters: {"id"=>"3051"}
I, [2023-06-16T12:18:52.834319#12836-6813060]  INFO -- : Completed 200 OK in 20ms (Views: 0.5ms | ActiveRecord: 10.9ms | Allocations: 6552)
I, [2023-06-16T12:18:54.231950#12840-7442460]  INFO -- : Started GET "/api/v1/users/image/1b271e5e13e2020d852416439e1a56f3" for 10.6.1.12 at 2023-06-16 12:18:54 +0200
I, [2023-06-16T12:18:54.232068#12836-6182400]  INFO -- : Started GET "/api/v1/users/image/8dbe2ea0fb4b02a8004e82b20124d2a8" for 10.6.1.12 at 2023-06-16 12:18:54 +0200
I, [2023-06-16T12:18:54.232772#12860-3394860]  INFO -- : Started GET "/api/v1/users/image/1d98f2c579c3d8f139caeee0e04057e6" for 10.6.1.12 at 2023-06-16 12:18:54 +0200
I, [2023-06-16T12:18:54.234636#12840-4673780]  INFO -- : Started GET "/api/v1/users/image/0037ad9bf7936e1978c0c0c05e2e130e" for 10.6.1.12 at 2023-06-16 12:18:54 +0200
I, [2023-06-16T12:18:54.234811#12836-6813100]  INFO -- : Started GET "/api/v1/users/image/b86eed811552bf192d7455d53d3d0ed0" for 10.6.1.12 at 2023-06-16 12:18:54 +0200
8

Are your users synced from an LDAP server or another external source?

9

No, all are internal in the database. The record exists in the table an is ok compared to other.

10

Did you try to update some fields like note for this specific user in the Rails console? Is this working?

11

Yes, the error is the same. The “User.find” finds the whole and correct record in the databse.

irb(main):006:0> u=User.find_by(login: 'e.mueck@abcd.de')
=>
#<User:0x00007f5b4bcfa140
...
irb(main):007:0> u.note="Fehler"
=> "Fehler"
irb(main):008:0> u.save
/opt/zammad/vendor/ruby-3.1.3/lib/ruby/3.1.0/psych/scalar_scanner.rb:43:in `match?': execution expired (Timeout::Error)
irb(main):009:0>
12

Do you have any trigger active that is being executed by changing this user? Please check.

13

No we’ve just one single trigger active to send an mail to answer to a new ticket.

14

This means there is no trigger, hm, ok… currently, I do not have an idea what’s going on. Sorry.

JFI: For sure, triggers are not executed when users are saved, just to be clear.

15

Can you please post the whole user record? Maybe there is something strange.

16

→ Thanks fliebe92, I sent you a PM

17

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