Unable to send emails from zammad

Technical assistance
1

Infos:

  • Used Zammad version: 5.1.X
  • Used Zammad installation type: (source, package, docker-compose, …) package
  • Operating system: Ubuntu 20.04
  • Browser + version: chrome

Expected behavior:

  • Emails are sent via google account authenticated via oauth2. I’ve monitored logs while attempting to send emails but do not see any pertinent errors. Mail sending was working fine until i removed the previous google SMTP / less secure apps setup.

Actual behavior:

  • Emails are received via google account / oauth2 but no messages are sent. Also tried falling back to a local MTA, and gmail SMTP

Steps to reproduce the behavior:

2

some additional info: i tried setting up email via MTA and gmail less secure apps and neither will send mail. I’ve verified that the oauth2 / gmail api requests are reaching google but still no mail. below is the logs i see that seem related:

I, [2022-04-08T17:31:26.107910 #615-3050540]  INFO -- :   Parameters: {"inbound"=>{"adapter"=>"imap", "options"=>{"realname"=>"grit1", "email"=>"email@adress.com", "group_id"=>"1", "host"=>"imap.gmail.com", "user"=>"email@adress.com", "password"=>"[FILTERED]", "ssl"=>"ssl", "port"=>"993", "folder"=>"", "keep_on_server"=>false}}, "outbound"=>{"adapter"=>"smtp", "options"=>{"host"=>"smtp.gmail.com", "user"=>"email@adress.com", "password"=>"[FILTERED]", "port"=>"587"}, "email"=>"email@adress.com"}, "meta"=>{"realname"=>"grit1", "email"=>"email@adress.com", "password"=>"[FILTERED]", "group_id"=>"1"}, "group_id"=>"1", "subject"=>"#764225eda57b45b6ef92"}
I, [2022-04-08T17:31:31.144379 #615-3050540]  INFO -- : fetching imap (imap.gmail.com/email@adress.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2022-04-08T17:31:31.844051 #615-3050540]  INFO -- : verify mode, fetch no emails #764225eda57b45b6ef92
I, [2022-04-08T17:31:35.672151 #620-7440]  INFO -- : Scheduler running...
I, [2022-04-08T17:31:35.694427 #620-7440]  INFO -- : Running job thread for 'Generate 'Session' data.' (Sessions.jobs) status is: sleep
I, [2022-04-08T17:31:35.694695 #620-7440]  INFO -- : Running job thread for 'Check 'Channel' streams.' (Channel.stream) status is: sleep
I, [2022-04-08T17:31:35.695301 #620-7440]  INFO -- : Running job thread for 'Process ticket escalations.' (Ticket.process_escalation) status is: sleep
I, [2022-04-08T17:31:35.695480 #620-7440]  INFO -- : Running job thread for 'Check channels.' (Channel.fetch) status is: sleep
I, [2022-04-08T17:31:35.696167 #620-7440]  INFO -- : Running job thread for 'Execute planned jobs.' (Job.run) status is: sleep
I, [2022-04-08T17:31:35.738217 #620-131820900]  INFO -- : execute Chat.cleanup_close (try_count 0)...
I, [2022-04-08T17:31:35.741975 #620-131820900]  INFO -- : ended Chat.cleanup_close took: 0.042311184 seconds.
I, [2022-04-08T17:31:36.141568 #615-2990440]  INFO -- : Started GET "/api/v1/channels_email?_=1649436405312" for (ip address) at 2022-04-08 17:31:36 +0000
I, [2022-04-08T17:31:36.154866 #615-2990440]  INFO -- : Processing by ChannelsEmailController#index as JSON
I, [2022-04-08T17:31:36.155011 #615-2990440]  INFO -- :   Parameters: {"_"=>"1649436405312"}
I, [2022-04-08T17:31:36.209637 #615-2990440]  INFO -- : Completed 200 OK in 54ms (Views: 4.1ms | ActiveRecord: 15.2ms | Allocations: 21074)
I, [2022-04-08T17:31:36.845606 #615-3050540]  INFO -- : fetching imap (imap.gmail.com/email@adress.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2022-04-08T17:31:37.742016 #615-3050540]  INFO -- : verify mode, fetch no emails #764225eda57b45b6ef92
I, [2022-04-08T17:31:41.436589 #620-128434420]  INFO -- : execute Channel.fetch (try_count 0)...
I, [2022-04-08T17:31:41.439273 #620-128434420]  INFO -- : ended Channel.fetch took: 0.029039347 seconds.
I, [2022-04-08T17:31:42.743374 #615-3050540]  INFO -- : fetching imap (imap.gmail.com/email@adress.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2022-04-08T17:31:43.336393 #615-3050540]  INFO -- : verify mode, fetch no emails #764225eda57b45b6ef92
I, [2022-04-08T17:31:48.337913 #615-3050540]  INFO -- : fetching imap (imap.gmail.com/email@adress.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2022-04-08T17:31:48.925063 #615-3050540]  INFO -- : verify mode, fetch no emails #764225eda57b45b6ef92
I, [2022-04-08T17:31:53.926681 #615-3050540]  INFO -- : fetching imap (imap.gmail.com/email@adress.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2022-04-08T17:31:54.739363 #615-3050540]  INFO -- : verify mode, fetch no emails #764225eda57b45b6ef92
I, [2022-04-08T17:31:59.740838 #615-3050540]  INFO -- : fetching imap (imap.gmail.com/email@adress.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2022-04-08T17:32:00.430308 #615-3050540]  INFO -- : verify mode, fetch no emails #764225eda57b45b6ef92
I, [2022-04-08T17:32:05.431696 #615-3050540]  INFO -- : fetching imap (imap.gmail.com/email@adress.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2022-04-08T17:32:06.081661 #615-3050540]  INFO -- : verify mode, fetch no emails #764225eda57b45b6ef92
I, [2022-04-08T17:32:06.137193 #615-183220]  INFO -- : Started GET "/api/v1/channels_email?_=1649436405313" for (ip address) at 2022-04-08 17:32:06 +0000
I, [2022-04-08T17:32:06.151341 #615-183220]  INFO -- : Processing by ChannelsEmailController#index as JSON
I, [2022-04-08T17:32:06.151524 #615-183220]  INFO -- :   Parameters: {"_"=>"1649436405313"}
I, [2022-04-08T17:32:06.187672 #615-183220]  INFO -- : Completed 200 OK in 36ms (Views: 3.0ms | ActiveRecord: 6.7ms | Allocations: 21074)
I, [2022-04-08T17:32:11.083104 #615-3050540]  INFO -- : fetching imap (imap.gmail.com/email@adress.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2022-04-08T17:32:11.465172 #620-128434420]  INFO -- : execute Channel.fetch (try_count 0)...
I, [2022-04-08T17:32:11.467862 #620-128434420]  INFO -- : ended Channel.fetch took: 0.023665954 seconds.
I, [2022-04-08T17:32:11.777305 #615-3050540]  INFO -- : verify mode, fetch no emails #764225eda57b45b6ef92
I, [2022-04-08T17:32:16.778797 #615-3050540]  INFO -- : fetching imap (imap.gmail.com/email@adress.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2022-04-08T17:32:17.490808 #615-3050540]  INFO -- : verify mode, fetch no emails #764225eda57b45b6ef92
I, [2022-04-08T17:32:17.493379 #615-3050540]  INFO -- : Completed 200 OK in 51385ms (Views: 0.6ms | ActiveRecord: 11.3ms | Allocations: 72557)
I, [2022-04-08T17:32:36.134560 #615-3045400]  INFO -- : Started GET "/api/v1/channels_email?_=1649436405314" for (ip address) at 2022-04-08 17:32:36 +0000
I, [2022-04-08T17:32:36.149034 #615-3045400]  INFO -- : Processing by ChannelsEmailController#index as JSON
I, [2022-04-08T17:32:36.149214 #615-3045400]  INFO -- :   Parameters: {"_"=>"1649436405314"}
I, [2022-04-08T17:32:36.216064 #615-3045400]  INFO -- : Completed 200 OK in 67ms (Views: 3.2ms | ActiveRecord: 11.9ms | Allocations: 21074)
I, [2022-04-08T17:32:41.535484 #620-128434420]  INFO -- : execute Channel.fetch (try_count 0)...
I, [2022-04-08T17:32:41.538421 #620-128434420]  INFO -- : ended Channel.fetch took: 0.065353717 seconds.
I, [2022-04-08T17:32:45.764893 #620-7440]  INFO -- : Scheduler running...
I, [2022-04-08T17:32:45.785764 #620-7440]  INFO -- : Running job thread for 'Generate 'Session' data.' (Sessions.jobs) status is: sleep
I, [2022-04-08T17:32:45.788858 #620-7440]  INFO -- : Running job thread for 'Check 'Channel' streams.' (Channel.stream) status is: sleep
I, [2022-04-08T17:32:45.789087 #620-7440]  INFO -- : Running job thread for 'Process ticket escalations.' (Ticket.process_escalation) status is: sleep
I, [2022-04-08T17:32:45.789247 #620-7440]  INFO -- : Running job thread for 'Check channels.' (Channel.fetch) status is: sleep
I, [2022-04-08T17:32:45.789938 #620-7440]  INFO -- : Running job thread for 'Execute planned jobs.' (Job.run) status is: sleep
I, [2022-04-08T17:33:06.133628 #615-875220]  INFO -- : Started GET "/api/v1/channels_email?_=1649436405315" for (ip address) at 2022-04-08 17:33:06 +0000
I, [2022-04-08T17:33:06.147721 #615-875220]  INFO -- : Processing by ChannelsEmailController#index as JSON
I, [2022-04-08T17:33:06.147883 #615-875220]  INFO -- :   Parameters: {"_"=>"1649436405315"}
I, [2022-04-08T17:33:06.203599 #615-875220]  INFO -- : Completed 200 OK in 56ms (Views: 3.8ms | ActiveRecord: 15.9ms | Allocations: 21074)
3

tried rolling back to a fresh install and setting up google oauth2. I am able to receive mail via the oauth2 connection but still cannot send mail. new production log output when replying to a ticket via email:

I, [2022-04-13T11:30:13.786877 #616-7440]  INFO -- : Running job thread for 'Check 'Channel' streams.' (Channel.stream) status is: sleep
I, [2022-04-13T11:30:13.787029 #616-7440]  INFO -- : Running job thread for 'Generate 'Session' data.' (Sessions.jobs) status is: sleep
I, [2022-04-13T11:30:13.787118 #616-7440]  INFO -- : Running job thread for 'Check channels.' (Channel.fetch) status is: sleep
I, [2022-04-13T11:30:13.787360 #616-7440]  INFO -- : Running job thread for 'Process ticket escalations.' (Ticket.process_escalation) status is: sleep
I, [2022-04-13T11:30:13.788431 #616-7440]  INFO -- : Running job thread for 'Execute planned jobs.' (Job.run) status is: sleep
I, [2022-04-13T11:30:32.900219 #616-11227440]  INFO -- : execute Channel.fetch (try_count 0)...
I, [2022-04-13T11:30:32.925750 #616-11227440]  INFO -- : fetching imap (imap.gmail.com/email@address.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=XOAUTH2)
I, [2022-04-13T11:30:33.679417 #616-11227440]  INFO -- :  - no message
I, [2022-04-13T11:30:33.723060 #616-11227440]  INFO -- : ended Channel.fetch took: 0.840143943 seconds.
I, [2022-04-13T11:31:03.936005 #616-11227440]  INFO -- : execute Channel.fetch (try_count 0)...
I, [2022-04-13T11:31:03.958615 #616-11227440]  INFO -- : fetching imap (imap.gmail.com/email@address.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=XOAUTH2)
I, [2022-04-13T11:31:04.808007 #616-11227440]  INFO -- :  - no message
I, [2022-04-13T11:31:04.857575 #616-11227440]  INFO -- : ended Channel.fetch took: 0.947659988 seconds.
I, [2022-04-13T11:31:08.987022 #609-182340]  INFO -- : Started PUT "/api/v1/taskbar/13" for 123.456.789.10 at 2022-04-13 11:31:08 -0700
I, [2022-04-13T11:31:09.012062 #609-182340]  INFO -- : Processing by TaskbarController#update as JSON
I, [2022-04-13T11:31:09.012262 #609-182340]  INFO -- :   Parameters: {"key"=>"Ticket-7582", "client_id"=>"123", "callback"=>"TicketZoom", "state"=>{"ticket"=>{}, "article"=>{"body"=>"[FILTERED]", "type"=>"email", "subtype"=>"reply", "in_reply_to"=>"<CAD(redacted)JA@mail.gmail.com>", "to"=>"(email address)", "from"=>"customer", "ticket_id"=>"7582", "content_type"=>"text/html", "sender_id"=>"1", "type_id"=>"1", "form_id"=>"874685186"}}, "params"=>{"ticket_id"=>7582, "overview_id"=>5, "init"=>true}, "prio"=>7, "notify"=>false, "active"=>true, "attachments"=>[], "updated_at"=>"2022-04-12T23:41:09.953Z", "id"=>"13"}
I, [2022-04-13T11:31:09.080912 #609-182340]  INFO -- : Completed 200 OK in 69ms (Views: 0.9ms | ActiveRecord: 20.5ms | Allocations: 14690)
I, [2022-04-13T11:31:11.031349 #609-181980]  INFO -- : Started PUT "/api/v1/tickets/7582?all=true" for 123.456.789.10 at 2022-04-13 11:31:11 -0700
I, [2022-04-13T11:31:11.052873 #609-181980]  INFO -- : Processing by TicketsController#update as JSON
I, [2022-04-13T11:31:11.053098 #609-181980]  INFO -- :   Parameters: {"number"=>"50009", "title"=>"test3", "group_id"=>"2", "owner_id"=>"3", "customer_id"=>25, "state_id"=>"2", "priority_id"=>"2", "article"=>{"from"=>"customer", "to"=>"(email address)", "cc"=>"", "subject"=>"", "body"=>"[FILTERED]", "content_type"=>"text/html", "ticket_id"=>7582, "type_id"=>1, "sender_id"=>1, "internal"=>false, "in_reply_to"=>"<CAD(redacted)JA@mail.gmail.com>", "form_id"=>"874685186", "subtype"=>"reply"}, "updated_at"=>"2022-04-13T18:30:06.421Z", "preferences"=>{"channel_id"=>3}, "organization_id"=>nil, "pending_time"=>nil, "id"=>"7582", "all"=>"true"}
I, [2022-04-13T11:31:11.448749 #609-181980]  INFO -- : Completed 200 OK in 394ms (Views: 5.6ms | ActiveRecord: 81.7ms | Allocations: 112120)
I, [2022-04-13T11:31:11.542536 #609-181000]  INFO -- : Started DELETE "/api/v1/upload_caches/874768995" for 123.456.789.10 at 2022-04-13 11:31:11 -0700
I, [2022-04-13T11:31:11.554441 #609-181000]  INFO -- : Processing by UploadCachesController#destroy as JSON
I, [2022-04-13T11:31:11.554577 #609-181000]  INFO -- :   Parameters: {"id"=>"874768995"}
I, [2022-04-13T11:31:11.585599 #609-181000]  INFO -- : Completed 200 OK in 31ms (Views: 0.3ms | ActiveRecord: 7.1ms | Allocations: 6920)
I, [2022-04-13T11:31:11.838900 #609-180920]  INFO -- : Started POST "/api/v1/integration/smime" for 123.456.789.10 at 2022-04-13 11:31:11 -0700
I, [2022-04-13T11:31:11.852182 #609-180920]  INFO -- : Processing by Integration::SMIMEController#search as JSON
I, [2022-04-13T11:31:11.852414 #609-180920]  INFO -- :   Parameters: {"ticket"=>{"group_id"=>"2", "owner_id"=>"3", "state_id"=>"2", "priority_id"=>"2"}, "article"=>{"body"=>"[FILTERED]", "type"=>"note", "internal"=>false, "form_id"=>"874768995", "shared_draft_id"=>"", "subtype"=>"", "in_reply_to"=>"", "to"=>"", "cc"=>"", "subject"=>""}}
I, [2022-04-13T11:31:11.891556 #609-180920]  INFO -- : Completed 200 OK in 39ms (Views: 0.5ms | ActiveRecord: 11.0ms | Allocations: 8032)
I, [2022-04-13T11:31:13.643105 #609-182280]  INFO -- : Started PUT "/api/v1/taskbar/13" for 123.456.789.10 at 2022-04-13 11:31:13 -0700
I, [2022-04-13T11:31:13.656216 #609-182280]  INFO -- : Processing by TaskbarController#update as JSON
I, [2022-04-13T11:31:13.656444 #609-182280]  INFO -- :   Parameters: {"key"=>"Ticket-7582", "client_id"=>"123", "callback"=>"TicketZoom", "state"=>{"ticket"=>{}, "article"=>{"form_id"=>"874768995"}}, "params"=>{"ticket_id"=>7582, "overview_id"=>5, "init"=>true}, "prio"=>7, "notify"=>false, "active"=>true, "attachments"=>[], "updated_at"=>"2022-04-12T23:41:09.953Z", "id"=>"13"}
I, [2022-04-13T11:31:13.718112 #609-182280]  INFO -- : Completed 200 OK in 61ms (Views: 0.9ms | ActiveRecord: 21.1ms | Allocations: 14384)
I, [2022-04-13T11:31:13.848716 #616-7440]  INFO -- : Scheduler running...
I, [2022-04-13T11:31:13.869440 #616-7440]  INFO -- : Running job thread for 'Check 'Channel' streams.' (Channel.stream) status is: sleep
I, [2022-04-13T11:31:13.869713 #616-7440]  INFO -- : Running job thread for 'Generate 'Session' data.' (Sessions.jobs) status is: sleep
I, [2022-04-13T11:31:13.869873 #616-7440]  INFO -- : Running job thread for 'Check channels.' (Channel.fetch) status is: sleep
I, [2022-04-13T11:31:13.870284 #616-7440]  INFO -- : Running job thread for 'Process ticket escalations.' (Ticket.process_escalation) status is: sleep
I, [2022-04-13T11:31:13.872109 #616-7440]  INFO -- : Running job thread for 'Execute planned jobs.' (Job.run) status is: sleep
4

Related to this issue, using the same gmail account with the email channel / app specific password works just fine send and receive. However Zammad has a banner saying that simple auth / gmail is being EoL’d and suggests migrating to oauth2. After converting to oauth2 email can be received but not sent. Selecting the revert migration option the issue sending email continues even though the config shows it is using the previously working setup.

5

issue was caused by zammad being left in import mode by another SA.
Setting.set(‘import_mode’, false)

6

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