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

caheissenberger · March 20, 2019, 5:21pm

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

MrGeneration · March 21, 2019, 1:28pm

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.

caheissenberger · March 21, 2019, 4:18pm

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

MrGeneration · March 21, 2019, 4:50pm

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.

caheissenberger · March 22, 2019, 10:29am

This solved our problem - Thank you very much

caheissenberger · March 22, 2019, 10:43am

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).

MrGeneration · March 22, 2019, 11:00am

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”.

caheissenberger · March 22, 2019, 12:54pm

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’

MrGeneration · March 22, 2019, 1:00pm

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

thorsteneckel · March 22, 2019, 1:14pm

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

caheissenberger · March 22, 2019, 2:14pm

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 (Sign in to Outlook 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 (Sign in to Outlook 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)

thorsteneckel · March 22, 2019, 2:44pm

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.

caheissenberger · March 22, 2019, 3:01pm

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

$

caheissenberger · March 22, 2019, 3:07pm

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 }”

$

thorsteneckel · March 22, 2019, 3:16pm

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

MrGeneration · March 22, 2019, 3:23pm

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 ;(

caheissenberger · March 22, 2019, 4:16pm

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"}>]

thorsteneckel · March 22, 2019, 4:27pm

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

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

caheissenberger · March 22, 2019, 5:37pm

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}

thorsteneckel · March 22, 2019, 6:05pm

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.