Verification of email for new customer sometimes fails

Technical assistance
1

Infos:

  • Used Zammad version: 7.0.2
  • Used Zammad installation type: docker-compose
  • Operating system: ubuntu 26.06
  • Browser + version: edge Version 150.0.4078.65 (Official build) (64-bit)

Expected behavior:

  • new customer creates account using the login form (“Register as new customer”)
  • welcome email is sent (and received) to his email address asking for email verification
  • customer click on provided link
  • web page is displayed and email is verified

Actual behavior:

  • new customer creates account using the login form (“Register as new customer”)
  • welcome email is sent (and received) to his email address asking for email verification
  • customer click on provided link
  • web page displayed showing error “Email could not be verified…”

Steps to reproduce the behavior:

  • it happens sometime, not every time, happened to me when registering with my yahoo.com email but not when using my outlook.com email
2

Here is a snippet from production.log when creating customer:

I, [2026-07-15T11:24:25.022199#112-84240] INFO – : Started POST “/api/v1/users” for 213.253.120.38 at 2026-07-15 11:24:25 +0200
I, [2026-07-15T11:24:25.025314#112-84240] INFO – : Processing by UsersController#create as JSON
I, [2026-07-15T11:24:25.025384#112-84240] INFO – : Parameters: {“login” => “[FILTERED]”, “firstname” => “Misko”, “lastname” => “TEST Y”, “email” => “[FILTERED]”, “password” => “[FILTERED]”, “role_ids” => , “signup” => true, “id” => “c-0”}
I, [2026-07-15T11:24:26.917596#116-84104] INFO – : 2026-07-15T11:24:26+0200: [Worker(host:portal pid:116 tid:84104)] Job SearchIndexJob [0b44cb30-364c-47f0-bfdf-3ebf372db3e5] from DelayedJob(default) with arguments: [“User”, 18] (id=87929) (queue=default) RUNNING
I, [2026-07-15T11:24:26.954120#116-84104] INFO – : 2026-07-15T11:24:26+0200: [Worker(host:portal pid:116 tid:84104)] Job SearchIndexJob [0b44cb30-364c-47f0-bfdf-3ebf372db3e5] from DelayedJob(default) with arguments: [“User”, 18] (id=87929) (queue=default) COMPLETED after 0.0364
I, [2026-07-15T11:24:26.956309#116-84104] INFO – : 2026-07-15T11:24:26+0200: [Worker(host:portal pid:116 tid:84104)] Job SearchIndexAssociationsJob [93135bf9-e996-44db-980d-af45dfc61a5f] from DelayedJob(default) with arguments: [“User”, 18] (id=87930) (queue=default) RUNNING
I, [2026-07-15T11:24:27.181825#116-84104] INFO – : 2026-07-15T11:24:27+0200: [Worker(host:portal pid:116 tid:84104)] Job SearchIndexAssociationsJob [93135bf9-e996-44db-980d-af45dfc61a5f] from DelayedJob(default) with arguments: [“User”, 18] (id=87930) (queue=default) COMPLETED after 0.2254
I, [2026-07-15T11:24:27.184662#116-84104] INFO – : 2026-07-15T11:24:27+0200: [Worker(host:portal pid:116 tid:84104)] Job AvatarCreateJob [e9d82e40-742b-4aaa-8e9a-5b90bde271a1] from DelayedJob(default) with arguments: [{“_aj_globalid” => “gid://zammad/User/18”}] (id=87931) (queue=default) RUNNING
I, [2026-07-15T11:24:27.627216#112-84240] INFO – : Completed 201 Created in 2602ms (Views: 0.1ms | ActiveRecord: 55.4ms (61 queries, 10 cached) | GC: 86.0ms)
I, [2026-07-15T11:24:27.909959#116-84104] INFO – : Can’t fetch image for ‘[FILTERED]’ (maybe no avatar available), http code: 404
I, [2026-07-15T11:24:27.923752#116-84104] INFO – : 2026-07-15T11:24:27+0200: [Worker(host:portal pid:116 tid:84104)] Job AvatarCreateJob [e9d82e40-742b-4aaa-8e9a-5b90bde271a1] from DelayedJob(default) with arguments: [{“_aj_globalid” => “gid://zammad/User/18”}] (id=87931) (queue=default) COMPLETED after 0.7390
I, [2026-07-15T11:24:27.926056#116-84104] INFO – : 2026-07-15T11:24:27+0200: [Worker(host:portal pid:116 tid:84104)] Job TransactionJob [78262f38-0950-406c-bd41-dba06a846808] from DelayedJob(default) with arguments: [{“object” => “User”, “object_id” => 18, “user_id” => 1, “created_at” => {“_aj_serialized” => “ActiveJob::Serializers::TimeWithZoneSerializer”, “value” => “2026-07-15T09:24:25.286340834Z”, “time_zone” => “Etc/UTC”}, “type” => “create”, “_aj_symbol_keys” => [“object”, “object_id”, “user_id”, “created_at”, “type”]}, {“interface_handle” => “application_server”, “_aj_symbol_keys” => [“interface_handle”]}] (id=87932) (queue=default) RUNNING
I, [2026-07-15T11:24:27.941212#116-84104] INFO – : 2026-07-15T11:24:27+0200: [Worker(host:portal pid:116 tid:84104)] Job TransactionJob [78262f38-0950-406c-bd41-dba06a846808] from DelayedJob(default) with arguments: [{“object” => “User”, “object_id” => 18, “user_id” => 1, “created_at” => {“_aj_serialized” => “ActiveJob::Serializers::TimeWithZoneSerializer”, “value” => “2026-07-15T09:24:25.286340834Z”, “time_zone” => “Etc/UTC”}, “type” => “create”, “_aj_symbol_keys” => [“object”, “object_id”, “user_id”, “created_at”, “type”]}, {“interface_handle” => “application_server”, “_aj_symbol_keys” => [“interface_handle”]}] (id=87932) (queue=default) COMPLETED after 0.0151

so it seems to me that everything went fine and email is received on the customer side:

image
image785×407 16.3 KB

3

but after clicking on the link from email I have an error " Email could not be verified. Please contact your administrator."

and this entries in the production.log:

I, [2026-07-15T11:31:13.497380#112-83968] INFO – : Started GET “/” for 213.253.120.38 at 2026-07-15 11:31:13 +0200
I, [2026-07-15T11:31:13.528791#112-83968] INFO – : Processing by InitController#index as HTML
I, [2026-07-15T11:31:13.542027#112-83968] INFO – : Rendered layout layouts/application.html.erb (Duration: 3.2ms | GC: 1.3ms)
I, [2026-07-15T11:31:13.545553#112-83968] INFO – : Completed 200 OK in 17ms (Views: 2.9ms | ActiveRecord: 4.5ms (6 queries, 1 cached) | GC: 7.9ms)
I, [2026-07-15T11:31:13.893111#112-83920] INFO – : Started POST “/api/v1/signshow” for 213.253.120.38 at 2026-07-15 11:31:13 +0200
I, [2026-07-15T11:31:13.906487#112-83920] INFO – : Processing by SessionsController#show as JSON
I, [2026-07-15T11:31:13.906544#112-83920] INFO – : Parameters: {“fingerprint” => “2079570594”}
I, [2026-07-15T11:31:14.116268#112-83920] INFO – : Completed 200 OK in 210ms (Views: 32.1ms | ActiveRecord: 41.3ms (158 queries, 35 cached) | GC: 15.1ms)
I, [2026-07-15T11:31:14.256739#112-83960] INFO – : Started GET “/api/v1/taskbar/init?=1784107873712" for 213.253.120.38 at 2026-07-15 11:31:14 +0200
I, [2026-07-15T11:31:14.259652#112-83960] INFO – : Processing by TaskbarController#init as JSON
I, [2026-07-15T11:31:14.259707#112-83960] INFO – : Parameters: {"” => “1784107873712”}
I, [2026-07-15T11:31:14.383915#112-83960] INFO – : Completed 200 OK in 124ms (Views: 1.3ms | ActiveRecord: 25.6ms (112 queries, 46 cached) | GC: 11.9ms)
I, [2026-07-15T11:31:14.473825#112-84200] INFO – : Started GET “/api/v1/translations/lang/en-us?=1784107873713" for 213.253.120.38 at 2026-07-15 11:31:14 +0200
I, [2026-07-15T11:31:14.477054#112-84200] INFO – : Processing by TranslationsController#lang as JSON
I, [2026-07-15T11:31:14.477115#112-84200] INFO – : Parameters: {"” => “1784107873713”, “locale” => “en-us”}
I, [2026-07-15T11:31:14.534524#112-84200] INFO – : Completed 200 OK in 57ms (Views: 5.0ms | ActiveRecord: 42.9ms (8 queries, 2 cached) | GC: 2.4ms)
I, [2026-07-15T11:31:14.750068#112-84240] INFO – : Started POST “/api/v1/users/email_verify” for 213.253.120.38 at 2026-07-15 11:31:14 +0200
I, [2026-07-15T11:31:14.752417#112-84240] INFO – : Processing by UsersController#email_verify as JSON
I, [2026-07-15T11:31:14.752469#112-84240] INFO – : Parameters: {“token” => “[FILTERED]”}
E, [2026-07-15T11:31:14.760173#112-84240] ERROR – : The provided token is invalid. (Exceptions::UnprocessableEntity)
app/controllers/users_controller.rb:291:in ‘UsersController#email_verify’
app/controllers/application_controller/handles_transitions.rb:16:in ‘ApplicationController::HandlesTransitions#handle_transaction’
I, [2026-07-15T11:31:14.761400#112-84240] INFO – : Completed 422 Unprocessable Entity in 9ms (Views: 0.2ms | ActiveRecord: 2.1ms (8 queries, 2 cached) | GC: 0.0ms)
I, [2026-07-15T11:31:14.782114#112-83968] INFO – : Started GET “/api/v1/cti/log?=1784107873714" for 213.253.120.38 at 2026-07-15 11:31:14 +0200
I, [2026-07-15T11:31:14.784690#112-83968] INFO – : Processing by CtiController#index as JSON
I, [2026-07-15T11:31:14.784741#112-83968] INFO – : Parameters: {"” => “1784107873714”}
I, [2026-07-15T11:31:14.792791#112-83968] INFO – : Completed 200 OK in 8ms (Views: 0.4ms | ActiveRecord: 2.0ms (13 queries, 6 cached) | GC: 0.0ms)
I, [2026-07-15T11:31:14.847175#112-83920] INFO – : Started GET “/api/v1/activity_stream?full=true&limit=25&=1784107873715" for 213.253.120.38 at 2026-07-15 11:31:14 +0200
I, [2026-07-15T11:31:14.850754#112-83920] INFO – : Processing by ActivityStreamController#show as JSON
I, [2026-07-15T11:31:14.852721#112-83920] INFO – : Parameters: {“full” => “true”, “limit” => “25”, "” => “1784107873715”}
I, [2026-07-15T11:31:14.852670#112-83960] INFO – : Started GET “/api/v1/first_steps?=1784107873716" for 213.253.120.38 at 2026-07-15 11:31:14 +0200
I, [2026-07-15T11:31:14.889069#112-83960] INFO – : Processing by FirstStepsController#index as JSON
I, [2026-07-15T11:31:14.889142#112-83960] INFO – : Parameters: {"” => “1784107873716”}
I, [2026-07-15T11:31:14.918847#112-83960] INFO – : Completed 200 OK in 30ms (Views: 0.1ms | ActiveRecord: 19.5ms (18 queries, 7 cached) | GC: 0.0ms)
I, [2026-07-15T11:31:14.930445#112-84200] INFO – : Started GET “/api/v1/ticket_overviews?=1784107873717" for 213.253.120.38 at 2026-07-15 11:31:14 +0200
I, [2026-07-15T11:31:14.932302#112-84240] INFO – : Started GET "/api/v1/ticket_overview?=1784107873718” for 213.253.120.38 at 2026-07-15 11:31:14 +0200
I, [2026-07-15T11:31:14.935646#112-84240] INFO – : Processing by TicketOverviewsController#data as JSON
I, [2026-07-15T11:31:14.936121#112-84240] INFO – : Parameters: {“" => “1784107873718”}
I, [2026-07-15T11:31:14.938381#112-84200] INFO – : Processing by TicketOverviewsController#show as JSON
I, [2026-07-15T11:31:14.938920#112-84200] INFO – : Parameters: {"” => “1784107873717”}
I, [2026-07-15T11:31:14.999125#112-83920] INFO – : Completed 200 OK in 146ms (Views: 2.7ms | ActiveRecord: 52.3ms (86 queries, 32 cached) | GC: 10.0ms)
I, [2026-07-15T11:31:15.044243#112-84240] INFO – : Completed 200 OK in 106ms (Views: 0.5ms | ActiveRecord: 70.2ms (51 queries, 13 cached) | GC: 3.3ms)
I, [2026-07-15T11:31:15.074702#112-84200] INFO – : Completed 200 OK in 135ms (Views: 4.1ms | ActiveRecord: 110.7ms (56 queries, 15 cached) | GC: 3.5ms)
I, [2026-07-15T11:31:16.420623#116-96936] INFO – : Closing session client (84880) thread
I, [2026-07-15T11:31:19.036448#116-84024] INFO – : execute Channel.fetch_async (try_count 0)…
I, [2026-07-15T11:31:19.043666#116-84024] INFO – : ended Channel.fetch_async took: 0.015467256 seconds.

Why I am getting this error “E, [2026-07-15T11:31:14.760173#112-84240] ERROR – : The provided token is invalid. (Exceptions::UnprocessableEntity)
app/controllers/users_controller.rb:291:in ‘UsersController#email_verify’
app/controllers/application_controller/handles_transitions.rb:16:in ‘ApplicationController::HandlesTransitions#handle_transaction’”???

4

AAAhaa!

Is there some form of matching a token that is left in the browser session with that url in the email?

I’ve managed to sucessfully verify that same email address when I opened existing url from email in separate incognito browser window…