[solved] SMTP STOREDRV.Submission.Exception / How to find the wrong Sender Email

Infos:

  • Used Zammad version: 2.10.x
  • Used Zammad installation source: deb
  • Operating system: ubuntu
  • Browser + version: no relevant

Expected behavior:

  • send emails with SMTP thru the configured office 365 settings

Actual behavior:

  • does work normally but sometimes stocks with the following error:

      Channel: Email::Account out Can't use Channel::Driver::Smtp: #<Net::SMTPFatalError: 554 5.2.0 STOREDRV.Submission.Exception:SendAsDeniedException.MapiExceptionSendAsDenied; Failed to process message due to a permanent exception with message Cannot submit message. 16.55847:DA210000, 17.43559:0000000094000000000000000000000000000000, 20.52176:140FAD86090010100A00C431, 20.50032:140FAD86791710100A00DD31, 0.35180:8E550000, 255.23226:0A00D431, 255.27962:0A000000, 255.27962:0E000000, 255.31418:0A000000, 16.55847:DA000000, 17.43559:000000009001000000000000B700000000000000, 20.52176:140FAD860900101003000136, 20.50032:140FAD86791710100A00DA36, 0.35180:44000000, 255.23226:4800D13D, 255.27962:0A000000, 255.27962:32000000, 255.17082:DC040000, 0.27745:0A003A66, 4.21921:DC040000, 255.27962:FA000000, 255.1494:64000000, 0.38698:00000000, 0.37692:0F010480, 0.44092:00000000, 0.40348:07000100, 0.34608:07000100, 0.55056:07000100, 0.42768:07000100, 0.56112:07000100, 0.52807:07000100, 4.33016:DC040000, 7.40748:010000000000010B2D346462, 7.57132:000000000000000031326533, 1.63016:32000000, 4.39640:DC040000, 8.45434:38B7A2F5CD79BC4BA0201CCBC41F850946000000, 5.10786:0000000031352E32302E313730392E3030393A5649315052303530314D42323137363A30333636623934612D363735372D346462392D393930622D3433383031313265336435610031003046, 255.1750:AA000000, 255.31418:03003866, 0.22753:AF000000, 255.21817:DC040000, 4.60547:DC040000, 0.21966:03002D67, 4.30158:DC040000 [Hostname=VI1PR0501MB2176.eurprd05.prod.outlook.com] >
    

    Failed to run background job #1 ‘TicketArticleCommunicateEmailJob’ 1 time(s) with 14 attempt(s).

we know that this might be because of a wrong sender but we have 30 senders configured and need an option to check the listed messages. Is there any other error log or database table with more specific information on the messages to allow us to find the broken sender email?

Steps to reproduce the behavior:

  • no

Well try your aliases you configured on top of the account you’re using.
Your exchange server says SendAsDeniedException so you proberbly try to send from an alias your account is not allowed to.

This is a exchange related problem, your exchange logs should help you here.

We use the Office365 Cloud Version - I have not access to logs.

Is there any way to access this messages (e.g. 17.43559:0000000094000000000000000000000000000000) in Zammad (database, file system,…):

Cannot submit message. 16.55847:DA210000, 17.43559:0000000094000000000000000000000000000000, 20.52176:140FAD86090010100A00C431, 20.50032:140FAD86791710100A00DD31, 0.35180:8E550000, 255.23226:0A00D431, 255.27962:0A000000, 255.27962:0E000000, 255.31418:0A000000, 16.55847:DA000000, 17.43559:000000009001000000000000B700000000000000, 20.52176:140FAD860900101003000136, 20.50032:140FAD86791710100A00DA36, 0.35180:44000000, 255.23226:4800D13D, 255.27962:0A000000, 255.27962:32000000, 255.17082:DC040000, 0.27745:0A003A66, 4.21921:DC040000, 255.2

Yes and no.
To find affected tickets, the following command might help you:

Ticket::Article.where('created_at > ?', '2019-03-15').where('body LIKE ?', "%STOREDRV.Submission%").to_a.select{ |a| a.ticket.articles.last == a }.map{ |a| a.ticket }

(run inside zammad run rails c)

Please note that the above command might be expensive in terms of CPU and I/O-time.
This will give you all tickets that are affected by the error.

Edit: If tickets are affected.

1 Like

This solved our problem - Thank you very much :slight_smile:

1 Like

Health Check Monitoring still reports an error even the mail (SMTP) channel is green and does not show up any errors. How can we reset the health of the system?

  • Failed to run background job #1 ‘TicketArticleCommunicateEmailJob’ 1 time(s) with 17 attempt(s).

The softest try would be to run

zammad run rails r "p Delayed::Job.where('last_error LIKE ?', \"%CommunicateEmailJob%\").each {|job| Delayed::Worker.new.run( Delayed::Job.find(job.id) )}" to reschedule the job.

If that doesn’t help try sending a mail via the affected channel (SMTP error state gets reset by this).
If you have no left over Background jobs a restart of Zammad-Service should help, maybe the scheduler gave up on it’s process “living”.

no change of the status after:

  • zammad run rails r “p Delaye…” => []
  • channel email all green
  • sending emails form both tickets wich have been identified with the first search command - all sent without error
  • service restarted ‘systemctl stop zammad’

@thorsteneckel can you help in resetting the state of that BackgroundJob?

There is an error with sending the Article for which this Job was created. After Running the command @MrGeneration posted the Job will be re-run and will print the error to the log. That’s what we should put our focus on :+1:

1 Like

I did run the command again and watched the log - but there are no errors
tail -f /var/log/zammad/production.log:

I, [2019-03-22T14:12:36.532639 #10182-47369722072920] INFO – : Setting.set(‘product_logo’, “18efc6d9d59a0b51cebd78a66486e816.png”)

I, [2019-03-22T14:12:42.181140 #4379-70252377495340] INFO – : Started GET “/api/v1/http_logs/sipgate.io?limit=50&_=1553259851351” for 213.164.21.18 at 2019-03-22 14:12:42 +0000

I, [2019-03-22T14:12:42.189526 #4379-70252377495340] INFO – : Processing by HttpLogsController#index as JSON

I, [2019-03-22T14:12:42.189670 #4379-70252377495340] INFO – : Parameters: {“limit”=>“50”, “_”=>“1553259851351”, “facility”=>“sipgate.io”}

I, [2019-03-22T14:12:42.202578 #4379-70252377495340] INFO – : Completed 200 OK in 13ms (Views: 0.8ms | ActiveRecord: 3.1ms)

I, [2019-03-22T14:12:44.572522 #4386-47347241545560] INFO – : Scheduler running…

I, [2019-03-22T14:12:44.579634 #4386-47347241545560] INFO – : Running job thread for ‘Check Channels’ (Channel.fetch) status is: sleep

I, [2019-03-22T14:12:44.580477 #4386-47347241545560] INFO – : Running job thread for ‘Import OTRS diff load’ (Import::OTRS.diff_worker) status is: sleep

I, [2019-03-22T14:12:44.581737 #4386-70195085621640] INFO – : Started job thread for ‘Process auto unassign tickets’ (Ticket.process_auto_unassign)…

I, [2019-03-22T14:12:44.586564 #4386-70195085621640] INFO – : execute Ticket.process_auto_unassign (try_count 0)…

I, [2019-03-22T14:12:44.592905 #4386-70195085621640] INFO – : …stopped thread for ‘Ticket.process_auto_unassign’

I, [2019-03-22T14:12:52.298709 #4379-47325801383500] INFO – : Started GET “/api/v1/monitoring/health_check?_=1553263745010” for 80.110.77.166 at 2019-03-22 14:12:52 +0000

I, [2019-03-22T14:12:52.305569 #4379-47325801383500] INFO – : Processing by MonitoringController#health_check as JSON

I, [2019-03-22T14:12:52.305671 #4379-47325801383500] INFO – : Parameters: {"_"=>“1553263745010”}

I, [2019-03-22T14:12:52.329412 #4379-47325801383500] INFO – : Completed 200 OK in 24ms (Views: 0.4ms | ActiveRecord: 5.1ms)

I, [2019-03-22T14:12:52.952141 #4386-70195081305720] INFO – : execute Channel.fetch (try_count 0)…

I, [2019-03-22T14:12:52.953885 #4386-70195081305720] INFO – : fetching pop3 (outlook.office365.com/login1@conda.online port=995,ssl=true)

I, [2019-03-22T14:12:53.424098 #4386-70195081305720] INFO – : - no message

I, [2019-03-22T14:12:53.424236 #4386-70195081305720] INFO – : done

I, [2019-03-22T14:12:54.581947 #4386-47347241545560] INFO – : Running job thread for ‘Generate Session data’ (Sessions.jobs) status is: sleep

I, [2019-03-22T14:12:54.582896 #4386-47347241545560] INFO – : Running job thread for ‘Check streams for Channel’ (Channel.stream) status is: sleep

I, [2019-03-22T14:12:54.583221 #4386-47347241545560] INFO – : Running job thread for ‘Process escalation tickets’ (Ticket.process_escalation) status is: sleep

I, [2019-03-22T14:12:54.583673 #4386-47347241545560] INFO – : Running job thread for ‘Execute jobs’ (Job.run) status is: sleep

I, [2019-03-22T14:13:02.253080 #4379-70252110769740] INFO – : Started GET “/api/v1/http_logs/sipgate.io?limit=50&_=1553259851352” for 213.164.21.18 at 2019-03-22 14:13:02 +0000

I, [2019-03-22T14:13:02.258475 #4379-70252110769740] INFO – : Processing by HttpLogsController#index as JSON

I, [2019-03-22T14:13:02.258559 #4379-70252110769740] INFO – : Parameters: {“limit”=>“50”, “_”=>“1553259851352”, “facility”=>“sipgate.io”}

I, [2019-03-22T14:13:02.269871 #4379-70252110769740] INFO – : Completed 200 OK in 11ms (Views: 0.7ms | ActiveRecord: 2.7ms)

I, [2019-03-22T14:13:03.474566 #4386-70195008085720] INFO – : execute Job.run (try_count 0)…

I, [2019-03-22T14:13:22.306585 #4379-70252444754320] INFO – : Started GET “/api/v1/http_logs/sipgate.io?limit=50&_=1553259851353” for 213.164.21.18 at 2019-03-22 14:13:22 +0000

I, [2019-03-22T14:13:22.311597 #4379-70252444754320] INFO – : Processing by HttpLogsController#index as JSON

I, [2019-03-22T14:13:22.311763 #4379-70252444754320] INFO – : Parameters: {“limit”=>“50”, “_”=>“1553259851353”, “facility”=>“sipgate.io”}

I, [2019-03-22T14:13:22.322385 #4379-70252444754320] INFO – : Completed 200 OK in 10ms (Views: 0.6ms | ActiveRecord: 2.6ms)

I, [2019-03-22T14:13:23.470218 #4386-70195081305720] INFO – : execute Channel.fetch (try_count 0)…

I, [2019-03-22T14:13:23.471877 #4386-70195081305720] INFO – : fetching pop3 (outlook.office365.com/login1@conda.online port=995,ssl=true)

I, [2019-03-22T14:13:23.914109 #4386-70195081305720] INFO – : - no message

I, [2019-03-22T14:13:23.914335 #4386-70195081305720] INFO – : done

I, [2019-03-22T14:13:27.299530 #4379-47325801383220] INFO – : Started GET “/api/v1/monitoring/health_check?_=1553263745011” for 80.110.77.166 at 2019-03-22 14:13:27 +0000

I, [2019-03-22T14:13:27.304462 #4379-47325801383220] INFO – : Processing by MonitoringController#health_check as JSON

I, [2019-03-22T14:13:27.304580 #4379-47325801383220] INFO – : Parameters: {"_"=>“1553263745011”}

I, [2019-03-22T14:13:27.323759 #4379-47325801383220] INFO – : Completed 200 OK in 19ms (Views: 0.3ms | ActiveRecord: 5.0ms)

Can you please run this via the Zammad rails console:

Delayed::Job.where('last_error LIKE ?', \"%CommunicateEmailJob%\").where('attempts > 0').map { |job| job.payload_object.args.first }

This will list all the ArticleIDs for which the sending failed. Should be probably only one e.g. [2423]

Now take this ArticleID and run the following command with it:

Ticket::Article.find(2423).preferences

If there were multiple ArticleIDs please run it with each of them and post the (anonymized) output here.

no results :frowning:
$ sudo zammad run rails r “Delayed::Job.where(‘last_error LIKE ?’, “%CommunicateEmailJob%”).where(‘attempts > 0’).map { |job| job.payload_object.args.first }”

$

result ist []:
$ sudo zammad run rails r “p Delayed::Job.where(‘last_error LIKE ?’, “%CommunicateEmailJob%”).where(‘attempts > 0’).map { |job| job.payload_object.args.first }”

[]

$

What if you remove the .where(‘attempts > 0’)?

Please do add p after “run rails r "”, otherwise you won’t get any output.
You seem to be running incomplete commands which do not do the trick ;(

still [] - I tried this and got some result:
sudo zammad run rails r “p Delayed::Job.where(‘last_error <> ?’,”").map { |job| job.payload_object }"

[#<ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper:0x000055bd54ec4548 @job_data={"job_class"=>"TicketArticleCommunicateEmailJob", "job_id"=>"326d8e22-2cbb-4d5a-96c1-f64aa0becc60", "provider_job_id"=>nil, "queue_name"=>"default", "priority"=>nil, "arguments"=>[21482], "executions"=>3, "locale"=>"en"}>]

Nice! Then we need to find out what’s wrong with that Article:

p Ticket::Article.find(21482).preferences

p Ticket::Article.find(21482).preferences

{“email_address_id”=>12, “delivery_retry”=>17, “delivery_channel_id”=>5, “delivery_status”=>“fail”, “delivery_status_message”=>“Can’t use Channel::Driver::Smtp: #<Net::SMTPFatalError: 554 5.2.0 STOREDRV.Submission.Exception:SendAsDeniedException.MapiExceptionSendAsDenied; Failed to process message due to a permanent exception with message Cannot submit message. 16.55847:CA210000, 17.43559:0000000094000000000000000100000000000000, 20.52176:140FC286000010103C050000, 20.50032:140FC2867017101041050000, 0.35180:0A00B380, 255.23226:46050000, 255.27962:0A000000, 255.27962:0E000000, 255.31418:0A000000, 16.55847:DA000000, 17.43559:000000009001000000000000A300000000000000, 20.52176:140FC2860000101003000136, 20.50032:140FC286701710100A00DA36, 0.35180:44000000, 255.23226:4800D13D, 255.27962:0A000000, 255.27962:32000000, 255.17082:DC040000, 0.27745:0A003A66, 4.21921:DC040000, 255.27962:FA000000, 255.1494:64000000, 0.38698:00000000, 0.37692:07000100, 0.44092:07000100, 0.40348:07000100, 0.34608:07000100, 0.55056:07000100, 0.42768:07000100, 0.56112:07000100, 0.52807:07000100, 4.33016:DC040000, 7.40748:010000000000010B2D346462, 7.57132:000000000000000031326533, 1.63016:32000000, 4.39640:DC040000, 8.45434:38B7A2F5CD79BC4BA0201CCBC41F850931324400, 5.10786:0000000031352E32302E313733302E3030303A5649315052303530314D42323137363A30333636623934612D363735372D346462392D393930622D3433383031313265336435610000000000, 255.1750:AA000000, 255.31418:03003866, 0.22753:AF000000, 255.21817:DC040000, 4.60547:DC040000, 0.21966:03002D67, 4.30158:DC040000 [Hostname=VI1PR0501MB2176.eurprd05.prod.outlook.com]\n>”, “delivery_status_date”=>Fri, 22 Mar 2019 08:56:37 UTC +00:00}

So the error is a response from outlook. If you find out what it means we can see what Zammad can do to avoid it. From the information we have so far it’s either a configuration or payload (email/article data) issue. No application error.
I’m sorry to say but I can’t give free community support on this kind of issue. However, I can answer questions if they arise.