Troubleshooting with the EMQ logfile

This page will provide some background into what the EMQ logging means.

 

Lifecycle

Installation

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 2021-03-11 15:31:27,961 UpmAsynchronousTaskManager:thread-2 INFO [service.scheduler.impl.PluginJobLauncher] EMQ: OnPluginEnabled - com.thepluginpeople.jira.emq 2021-03-11 15:31:27,961 UpmAsynchronousTaskManager:thread-2 INFO [service.scheduler.impl.PluginJobLauncher] EMQ: onLifecycleEvent PLUGIN_ENABLED 2021-03-11 15:31:27,961 UpmAsynchronousTaskManager:thread-2 INFO [service.scheduler.impl.PluginJobLauncher] EMQ: Got the last lifecycle event... Time to get started! 2021-03-11 15:31:27,961 UpmAsynchronousTaskManager:thread-2 INFO [service.scheduler.impl.PluginJobLauncher] EMQ: unregisterListener() 2021-03-11 15:31:27,961 UpmAsynchronousTaskManager:thread-2 INFO [service.scheduler.impl.PluginJobLauncher] EMQ: LAUNCH! 2021-03-11 15:31:27,961 UpmAsynchronousTaskManager:thread-2 INFO [service.scheduler.impl.PluginJobLauncher] EMQ: initActiveObjects() 2021-03-11 15:31:28,365 UpmAsynchronousTaskManager:thread-2 INFO [service.scheduler.impl.PluginJobLauncher] EMQ: clearupJobExecution() 2021-03-11 15:31:28,367 UpmAsynchronousTaskManager:thread-2 INFO [service.scheduler.impl.PluginJobLauncher] EMQ: registerJobRunner() 2021-03-11 15:31:28,367 UpmAsynchronousTaskManager:thread-2 INFO [service.scheduler.impl.PluginJobLauncher] EMQ: launchScheduledFlushJob() 2021-03-11 15:31:28,367 UpmAsynchronousTaskManager:thread-2 INFO [service.scheduler.impl.PluginScheduleManagerImpl] Scheduling job with jitter=9746: JobConfig[jobRunnerKey=com.thepluginpeople.jira.emq:EMQScheduledFlushJob,runMode=RUN_ONCE_PER_CLUSTER,schedule=Schedule[type=INTERVAL,intervalScheduleInfo=IntervalScheduleInfo[firstRunTime=Thu Mar 11 15:31:53 GMT 2021,intervalInMillis=90000]],parameters={}] 2021-03-11 15:31:28,368 UpmAsynchronousTaskManager:thread-2 INFO [service.scheduler.impl.PluginScheduleManagerImpl] We will be replacing an existing job with jobId=com.thepluginpeople.jira.emq:EMQScheduledFlushJob: LazyJobDetails[jobId=com.thepluginpeople.jira.emq:EMQScheduledFlushJob,jobRunnerKey=com.thepluginpeople.jira.emq:EMQScheduledFlushJob,runMode=RUN_ONCE_PER_CLUSTER,schedule=Schedule[type=INTERVAL,intervalScheduleInfo=IntervalScheduleInfo[firstRunTime=Thu Mar 11 15:24:20 GMT 2021,intervalInMillis=120000]],nextRunTime=Thu Mar 11 15:32:20 GMT 2021,rawParameters=(null),delegate=(unresolved)] 2021-03-11 15:31:28,369 UpmAsynchronousTaskManager:thread-2 INFO [service.scheduler.impl.PluginScheduleManagerImpl] Successfully scheduled jobId=com.thepluginpeople.jira.emq:EMQScheduledFlushJob, scheduled for= 2021-03-11 15:31:28,369 UpmAsynchronousTaskManager:thread-2 INFO [service.scheduler.impl.PluginScheduleManagerImpl] Scheduling job with jitter=7446: JobConfig[jobRunnerKey=com.thepluginpeople.jira.emq:EMQFlushMonitorJob,runMode=RUN_ONCE_PER_CLUSTER,schedule=Schedule[type=INTERVAL,intervalScheduleInfo=IntervalScheduleInfo[firstRunTime=Thu Mar 11 15:31:50 GMT 2021,intervalInMillis=600000]],parameters={}] 2021-03-11 15:31:28,369 UpmAsynchronousTaskManager:thread-2 INFO [service.scheduler.impl.PluginScheduleManagerImpl] We will be replacing an existing job with jobId=com.thepluginpeople.jira.emq:EMQFlushMonitorJob: LazyJobDetails[jobId=com.thepluginpeople.jira.emq:EMQFlushMonitorJob,jobRunnerKey=com.thepluginpeople.jira.emq:EMQFlushMonitorJob,runMode=RUN_ONCE_PER_CLUSTER,schedule=Schedule[type=INTERVAL,intervalScheduleInfo=IntervalScheduleInfo[firstRunTime=Thu Mar 11 15:24:17 GMT 2021,intervalInMillis=600000]],nextRunTime=Thu Mar 11 15:34:17 GMT 2021,rawParameters=(null),delegate=(unresolved)] 2021-03-11 15:31:28,370 UpmAsynchronousTaskManager:thread-2 INFO [service.scheduler.impl.PluginScheduleManagerImpl] Successfully scheduled jobId=com.thepluginpeople.jira.emq:EMQFlushMonitorJob, scheduled for= 2021-03-11 15:31:28,370 UpmAsynchronousTaskManager:thread-2 INFO [service.scheduler.impl.PluginJobLauncher] EMQ: launched successfully

 

Jobs

Scheduled Flush

1 2021-03-11 15:35:53,114 Caesium-1-2 DEBUG [service.scheduler.impl.PluginJobRunnerImpl] Running job type: EMQScheduledFlushJob

This job will:

  • flushDefaultQueues() – part of this it to schedule the next run of the EMQScheduledFlushJob

  • flushUserQueues()

  • send ImmedateDelivery messages

  • flushErrorMessages()

Flush monitor Job

1 2 3 4 5 2021-03-11 16:01:50,820 Caesium-1-4 DEBUG [service.scheduler.jobs.EMQFlushMonitorJob] Flush Monitor job running 2021-03-11 16:01:50,820 Caesium-1-4 DEBUG [service.scheduler.impl.PluginScheduleManagerImpl] Job[EMQScheduledFlushJob] is OK and has yet to run, next run: Thu Mar 11 16:01:53 GMT 2021 2021-03-11 16:01:50,820 Caesium-1-4 INFO [service.scheduler.jobs.EMQFlushMonitorJob] [Jira Server] will test for IMMEDS 2021-03-11 16:01:50,823 Caesium-1-4 DEBUG [service.scheduler.jobs.EMQFlushMonitorJob] [Jira SERVER] No unsent IMMEDIATE delivery messages found 2021-03-11 16:01:53,115 Caesium-1-4 DEBUG [service.scheduler.impl.PluginJobRunnerImpl] Running job type: EMQScheduledFlushJob

This job does two things:

1) It’s a safeguard against the EMQScheduledFlushJob’s next fire date becoming out of date (to execute at a time that has already passed).

2) Will attempt to send IMMEDIATE delivery messages that have been sent in the previous 10 minutes.

JIRA Event Source

When the event source includes JIRA, it means EMQ is listening for events from Jira only, not apps like JEMH.

Immediate Delivery

Immediate Delivery Event Processing

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 2021-03-11 16:28:15,547 http-nio-8080-exec-25 DEBUG [jira.emq.queue.EMQBootstrap] onIssueEvent() handling: 2021-03-11 16:28:15,551 http-nio-8080-exec-25 DEBUG [jira.emq.queue.QueueManagerImpl] Matched DEFAULT queue [EMQ TEST project queue with "EMQ default" mailbox] for event 6 on TEST-1 2021-03-11 16:28:15,555 http-nio-8080-exec-25 DEBUG [jira.emq.queue.RecipientResolverImpl] Processing Notification Scheme type: ----------------- Current_Assignee 2021-03-11 16:28:15,555 http-nio-8080-exec-25 DEBUG [jira.emq.queue.RecipientResolverImpl] No TemplateSet defined 2021-03-11 16:28:15,563 http-nio-8080-exec-25 DEBUG [jira.emq.queue.RecipientResolverImpl] Notification scheme recipients found: 1 2021-03-11 16:28:15,564 http-nio-8080-exec-25 DEBUG [jira.emq.queue.RecipientResolverImpl] Initiating User [admin] will NOT be notified. Mail Queue NotifyMeCondition is: USER_PREFERENCE 2021-03-11 16:28:15,564 http-nio-8080-exec-25 DEBUG [jira.emq.queue.RecipientResolverImpl] removed initiating user, and then there were: 1 2021-03-11 16:28:15,564 http-nio-8080-exec-25 DEBUG [jira.emq.queue.RecipientResolverImpl] removed users due to comment security, and then there were: 1 2021-03-11 16:28:15,564 http-nio-8080-exec-25 DEBUG [jira.emq.queue.RecipientResolverImpl] Processing Notification Scheme type: ----------------- Current_Reporter 2021-03-11 16:28:15,564 http-nio-8080-exec-25 DEBUG [jira.emq.queue.RecipientResolverImpl] No TemplateSet defined 2021-03-11 16:28:15,564 http-nio-8080-exec-25 DEBUG [jira.emq.queue.RecipientResolverImpl] Notification scheme recipients found: 1 2021-03-11 16:28:15,564 http-nio-8080-exec-25 DEBUG [jira.emq.queue.RecipientResolverImpl] Initiating User [admin] will NOT be notified. Mail Queue NotifyMeCondition is: USER_PREFERENCE 2021-03-11 16:28:15,564 http-nio-8080-exec-25 DEBUG [jira.emq.queue.RecipientResolverImpl] removed initiating user, and then there were: 1 2021-03-11 16:28:15,564 http-nio-8080-exec-25 DEBUG [jira.emq.queue.RecipientResolverImpl] removed users due to comment security, and then there were: 1 2021-03-11 16:28:15,564 http-nio-8080-exec-25 DEBUG [jira.emq.queue.RecipientResolverImpl] Processing Notification Scheme type: ----------------- All_Watchers 2021-03-11 16:28:15,564 http-nio-8080-exec-25 DEBUG [jira.emq.queue.RecipientResolverImpl] No TemplateSet defined 2021-03-11 16:28:15,565 http-nio-8080-exec-25 DEBUG [jira.emq.queue.RecipientResolverImpl] Notification scheme recipients found: 1 2021-03-11 16:28:15,565 http-nio-8080-exec-25 DEBUG [jira.emq.queue.RecipientResolverImpl] Initiating User [admin] will NOT be notified. Mail Queue NotifyMeCondition is: USER_PREFERENCE 2021-03-11 16:28:15,565 http-nio-8080-exec-25 DEBUG [jira.emq.queue.RecipientResolverImpl] removed initiating user, and then there were: 1 2021-03-11 16:28:15,565 http-nio-8080-exec-25 DEBUG [jira.emq.queue.RecipientResolverImpl] removed users due to comment security, and then there were: 1 2021-03-11 16:28:15,585 http-nio-8080-exec-25 DEBUG [jira.emq.queue.ActionEvaluatorImpl] Resolving action for user JIRAUSER10100 2021-03-11 16:28:15,593 http-nio-8080-exec-25 DEBUG [jira.emq.queue.ActionEvaluatorImpl] Action IMMEDIATE resolved for user JIRAUSER10100 2021-03-11 16:28:16,228 http-nio-8080-exec-25 DEBUG [jira.emq.manager.MailEntityManagerImpl] Mail Entity 2 has been created. 2021-03-11 16:28:16,230 http-nio-8080-exec-25 DEBUG [jira.emq.queue.MailEntityProcessorImpl] 1 mail items to be sent soon using queue 1 EMQ TEST project queue with "EMQ default" mailbox 2021-03-11 16:28:16,234 pool-49-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Mail Entity Processor Task has been created 2021-03-11 16:28:16,235 pool-49-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Waiting 10000 ms before more mail is sent 2021-03-11 16:28:16,235 pool-49-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Collected Mail Entity [id=2, qId=1, qName=EMQ TEST project queue with "EMQ default" mailbox] for delivery [type=IMMEDIATE] 2021-03-11 16:28:16,235 pool-49-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Waiting 10000 ms before more mail is sent

The above ‘creates’ the Mail Entities ready for sending. We send on a different Thread to ensure the Jira user isn’t blocked by this long running operation.

Immediate Delivery Mail Entity Sending

1 2 3 4 5 6 7 8 9 10 11 12 2021-03-11 16:28:26,235 pool-49-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] No new Mail Entities found 2021-03-11 16:28:26,235 pool-49-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Sending 1 collected Mail Entities 2021-03-11 16:28:26,238 pool-49-thread-1 DEBUG [jira.emq.queue.MailSenderJiraSMTPImpl] Starting to open connection 2021-03-11 16:28:26,259 pool-49-thread-1 DEBUG [jira.emq.queue.MailSenderJiraSMTPImpl] Connection [host:smtp.mailtrap.io, from: emq-default@blah.com] opened 2021-03-11 16:28:26,263 pool-49-thread-1 DEBUG [jira.emq.queue.MailQueueSenderImpl] 1 mail items to be sent NOW using queue 1: EMQ TEST project queue with "EMQ default" mailbox 2021-03-11 16:28:26,278 pool-49-thread-1 DEBUG [jira.emq.queue.AttachmentDownloaderImpl] Trying to download image from 'http://localhost:8080/images/mail/atlassian-email-logo.png' for inlining 2021-03-11 16:28:26,297 pool-49-thread-1 DEBUG [jira.emq.queue.MailQueueSenderImpl] Sleeping for 100 ms before sending a new email 2021-03-11 16:28:26,398 pool-49-thread-1 DEBUG [jira.emq.queue.MailQueueSenderImpl] Sending Mail Entity 2 using connection [qId=3, qName=EMQ default, qFrom=emq-default@blah.com] with actual msg from: emq-default@blah.com 2021-03-11 16:28:27,829 pool-49-thread-1 DEBUG [jira.emq.queue.MailSenderJiraSMTPImpl] Message [from=emq-default@blah.com, subject=(TEST-1) This is a starting email template, update as required] sent in 1431 ms 2021-03-11 16:28:27,836 pool-49-thread-1 DEBUG [jira.emq.queue.MailQueueSenderImpl] Sending Mail Entity 2 has been sent using connection [qId=3, qName=EMQ default, qFrom=emq-default@blah.com] with actual msg from: emq-default@blah.com 2021-03-11 16:28:27,836 pool-49-thread-1 DEBUG [jira.emq.queue.MailSenderJiraSMTPImpl] Closing SMTP server session [id=null, host=smtp.mailtrap.io, user=edbb06bded0edb, defaultFrom=emq-default@blah.com] 2021-03-11 16:28:27,838 pool-49-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Waiting 10000 ms before more mail is sent

As shown here, the logs will expose what item, the email subject (with issuekey) will shown the EMQ queues ‘from:’ address, as well as the supplied “message” from: address (which matters more when JEMH is involved where the mail is actually generated outside EMQ).

Immediate Delivery Queue Configuration

Immediate Delivery Auditing

An IMMEDIATE delivery queue doesn’t create digest Mail Items, hence the Digest Items section will be empty:

Looking at the Mail Items view, we can see that the IMMEDIATE delivery succeeded (a comment was made)

Digested Delivery

Digested Delivery Configuration

For testing, we set the digest period to 5mins:

Digested Delivery Queue Configuration

Digested Delivery Event Processing

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 2021-03-11 17:51:12,861 http-nio-8080-exec-18 DEBUG [jira.emq.queue.EMQBootstrap] onIssueEvent() handling: 2021-03-11 17:51:12,864 http-nio-8080-exec-18 DEBUG [jira.emq.queue.QueueManagerImpl] Matched DEFAULT queue [EMQ TEST project queue with "EMQ default" mailbox] for event 6 on TEST-1 2021-03-11 17:51:12,864 http-nio-8080-exec-18 DEBUG [jira.emq.queue.RecipientResolverImpl] Processing Notification Scheme type: ----------------- Current_Assignee 2021-03-11 17:51:12,864 http-nio-8080-exec-18 DEBUG [jira.emq.queue.RecipientResolverImpl] No TemplateSet defined 2021-03-11 17:51:12,864 http-nio-8080-exec-18 DEBUG [jira.emq.queue.RecipientResolverImpl] Notification scheme recipients found: 1 2021-03-11 17:51:12,864 http-nio-8080-exec-18 DEBUG [jira.emq.queue.RecipientResolverImpl] Initiating User [admin] will NOT be notified. Mail Queue NotifyMeCondition is: USER_PREFERENCE 2021-03-11 17:51:12,864 http-nio-8080-exec-18 DEBUG [jira.emq.queue.RecipientResolverImpl] removed initiating user, and then there were: 1 2021-03-11 17:51:12,864 http-nio-8080-exec-18 DEBUG [jira.emq.queue.RecipientResolverImpl] removed users due to comment security, and then there were: 1 2021-03-11 17:51:12,864 http-nio-8080-exec-18 DEBUG [jira.emq.queue.RecipientResolverImpl] Processing Notification Scheme type: ----------------- Current_Reporter 2021-03-11 17:51:12,864 http-nio-8080-exec-18 DEBUG [jira.emq.queue.RecipientResolverImpl] No TemplateSet defined 2021-03-11 17:51:12,864 http-nio-8080-exec-18 DEBUG [jira.emq.queue.RecipientResolverImpl] Notification scheme recipients found: 1 2021-03-11 17:51:12,864 http-nio-8080-exec-18 DEBUG [jira.emq.queue.RecipientResolverImpl] Initiating User [admin] will NOT be notified. Mail Queue NotifyMeCondition is: USER_PREFERENCE 2021-03-11 17:51:12,864 http-nio-8080-exec-18 DEBUG [jira.emq.queue.RecipientResolverImpl] removed initiating user, and then there were: 1 2021-03-11 17:51:12,864 http-nio-8080-exec-18 DEBUG [jira.emq.queue.RecipientResolverImpl] removed users due to comment security, and then there were: 1 2021-03-11 17:51:12,864 http-nio-8080-exec-18 DEBUG [jira.emq.queue.RecipientResolverImpl] Processing Notification Scheme type: ----------------- All_Watchers 2021-03-11 17:51:12,864 http-nio-8080-exec-18 DEBUG [jira.emq.queue.RecipientResolverImpl] No TemplateSet defined 2021-03-11 17:51:12,865 http-nio-8080-exec-18 DEBUG [jira.emq.queue.RecipientResolverImpl] Notification scheme recipients found: 1 2021-03-11 17:51:12,865 http-nio-8080-exec-18 DEBUG [jira.emq.queue.RecipientResolverImpl] Initiating User [admin] will NOT be notified. Mail Queue NotifyMeCondition is: USER_PREFERENCE 2021-03-11 17:51:12,865 http-nio-8080-exec-18 DEBUG [jira.emq.queue.RecipientResolverImpl] removed initiating user, and then there were: 1 2021-03-11 17:51:12,865 http-nio-8080-exec-18 DEBUG [jira.emq.queue.RecipientResolverImpl] removed users due to comment security, and then there were: 1 2021-03-11 17:51:12,872 http-nio-8080-exec-18 DEBUG [jira.emq.queue.ActionEvaluatorImpl] Action DIGEST resolved for [username=assignee, email=assignee@localhost, userkey=JIRAUSER10100] 2021-03-11 17:51:12,911 http-nio-8080-exec-18 DEBUG [jira.emq.manager.DigestEntityManagerImpl] Digest Entity 4 has been created.

Here you can see EMQ gets an event, then work through the notification scheme to resolve recipient to be notified, here one Digest Entity was created. EMQ > Auditing > Mail Items is empty, we find a Digest Item, ready for sending.

You can see the related Digest Entity ID (#4) through EMQ > Auditing > Digest Items, and view the actual digested content through the drop down icon far right:

Digested Delivery Mail Sending

Granted this is not overly verbose!

1 2 3 4 5 2021-03-11 17:56:05,536 Caesium-1-3 DEBUG [service.scheduler.impl.PluginJobRunnerImpl] Running job type: EMQScheduledFlushJob 2021-03-11 17:56:05,536 Caesium-1-3 DEBUG [service.scheduler.jobs.EMQScheduledFlushJob] Flushing queues 2021-03-11 17:56:05,555 Caesium-1-3 DEBUG [jira.emq.queue.DigestEntityProcessorImpl] 1 Digest Entities will be processed now. 2021-03-11 17:56:05,570 Caesium-1-3 DEBUG [service.scheduler.jobs.EMQScheduledFlushJob] Next job scheduled for : Thu Mar 11 18:01:05 GMT 2021 2021-03-11 17:56:05,701 pool-56-thread-1 DEBUG [jira.emq.manager.MailEntityManagerImpl] Mail Entity 4 has been created.

Digested items

This shows the ‘events’ that have occurred that have been consumed

Digest notifications

The EMQ > Auditing > Mail items view shows the sent digest notifications per recipient:

The sent digest can be viewed via the drop down on the far right:

About EMQ > Digest History

This view shows historic Digested content flush executions and outcomes, giving a summary of emails sent, and indicating if problems were found during sending:

API Source

When EMQ Event Source is API, it only accepts input from apps like JEMH. This way, events from Jira can only get to EMQ through the expected path of JEMH notifications.

API specific features

With the API source, apps like JEMH can drive EMQ with a pre-rendered and pre-built email. In this scenario, the email will already be fully populated with a from: address. When Digest Delivery is being done, the sender address is not retained, only the body html/text is. Therefore digest delivery will continue to use the Queue specific sender address for mail that EMQ creates with the digested content within. The main issue here comes up with Immediate Delivery and is covered below.

JEMH Logging (success)

This is from the jemh.log showing that JEMH built the email and piped through to EMQ.

1 2 3 4 5 6 2021-03-13 16:24:43,308 http-nio-8080-exec-16 DEBUG [jira.emh.service.DefaultJEMHMessageManager] digestNotification() TEST-5 for recipient: assignee@localhost 2021-03-13 16:24:43,308 http-nio-8080-exec-16 DEBUG [jira.emh.service.DefaultJEMHMessageManager] --- Digest starting 2021-03-13 16:24:43,308 http-nio-8080-exec-16 DEBUG [service.optional.emq.EmqAccessor] The EMQ Service Class IEMQOperationsManager is available, getting the ServiceFactory 2021-03-13 16:24:43,309 http-nio-8080-exec-16 DEBUG [emh.service.optional.OptionalService] tracked service: com.thepluginpeople.jira.emq.queue.EMQOperationsManagerImpl@3622f4bf 2021-03-13 16:24:43,309 http-nio-8080-exec-16 DEBUG [service.optional.emq.Emq] EMQ is available 2021-03-13 16:24:43,346 http-nio-8080-exec-16 DEBUG [jira.emh.service.DefaultJEMHMessageManager] --- Digest ended

JEMH Logging (failure)

This is also from the jemh.log, it shows the outcome when EMQ is not configured to listen to the API. JEMH will trigger a default delivery in this case using the standard Jira mail server. EMQ itself, listening to Jira events, will also get that event and queue a delivery.

1 2 3 4 5 6 7 2021-03-13 16:18:06,889 http-nio-8080-exec-1 DEBUG [jira.emh.service.DefaultJEMHMessageManager] digestNotification() TEST-5 for recipient: reporter@localhost 2021-03-13 16:18:06,889 http-nio-8080-exec-1 DEBUG [jira.emh.service.DefaultJEMHMessageManager] --- Digest starting 2021-03-13 16:18:06,890 http-nio-8080-exec-1 DEBUG [service.optional.emq.EmqAccessor] The EMQ Service Class IEMQOperationsManager is available, getting the ServiceFactory 2021-03-13 16:18:06,890 http-nio-8080-exec-1 DEBUG [emh.service.optional.OptionalService] tracked service: com.thepluginpeople.jira.emq.queue.EMQOperationsManagerImpl@3622f4bf 2021-03-13 16:18:06,890 http-nio-8080-exec-1 DEBUG [service.optional.emq.Emq] EMQ is available 2021-03-13 16:18:06,890 http-nio-8080-exec-1 DEBUG [jira.emh.service.DefaultJEMHMessageManager] --- Digest ended 2021-03-13 16:18:06,890 http-nio-8080-exec-1 ERROR [jira.emh.service.DefaultJEMHMessageManager] Message was NOT digested for some reason, fallbacking back to standard delivery

Immediate Delivery

Queue Selection

When driven through the API, the calling app (typically JEMH) can also supply a numeric queueId that would be used to drive delivery. If no queueId is defined, and if no queue ‘matches’ the causal IssueEvent (typically by project) then default queue will be used. This lack of queue definition can lead to a mismatch between the built email’s from: address, and the sending account, covered next.

When the API delivered mail has a from: address different to the queue’s

The problem that can come up is with Immediate Delivery is being done where EMQ will take the email supplied by the API source and use that verbatim, sending to the queue SMTP server for delivery. Whether the queue SMTP server allows the from: address to be what you have configured is mail-server dependant. Gmail for example will fallback to the ‘default’ mailbox sender address ‘and just work’, O365 will likely fail with:

1 MailException: com.sun.mail.smtp.SMTPSendFailedException: 554 5.2.0 STOREDRV.Submission.Exception:SendAsDeniedException.MapiExceptionSendAsDenied; Failed to process message due to a permanent exception with message Cannot submit message.

The important keyword is MapiExceptionSendAsDenied, which leads to:

To diagnose this kind of thing, you will need to look to the logs to resolve differences between the queue authentication / from: address, and what the mail from: address actually was. Simply, if your queue account is not able to send on behalf of the address you nominate, the mail will not send, and this will block the sending queue.

Happy path logging from API

The mail is received, and queued for delivery

1 2 3 4 5 6 7 8 9 10 11 12 2021-03-13 16:42:30,652 http-nio-8080-exec-13 DEBUG [jira.emq.queue.EMQBootstrap] digestNotification() for usable event: TEST-5, subject: (TEST-5) This is a starting email template, update as required 2021-03-13 16:42:30,655 http-nio-8080-exec-13 DEBUG [jira.emq.queue.QueueManagerImpl] Matched DEFAULT queue [EMQ TEST project queue with "EMQ default" mailbox] for event 6 on TEST-5 2021-03-13 16:42:30,660 http-nio-8080-exec-13 DEBUG [jira.emq.queue.JiraServiceUtils] Email match [assignee@localhost] with [key=JIRAUSER10100,username=assignee, email=assignee@localhost] 2021-03-13 16:42:30,660 http-nio-8080-exec-13 DEBUG [jira.emq.queue.JiraServiceUtils] User assignee is active, getting directoryUser 2021-03-13 16:42:30,660 http-nio-8080-exec-13 DEBUG [jira.emq.queue.JiraServiceUtils] Got ACTIVE directory user: assignee, directoryId: 1 2021-03-13 16:42:30,669 http-nio-8080-exec-13 DEBUG [jira.emq.queue.ActionEvaluatorImpl] Action IMMEDIATE resolved for [username=assignee, email=assignee@localhost, userkey=JIRAUSER10100] 2021-03-13 16:42:30,690 http-nio-8080-exec-13 DEBUG [jira.emq.manager.MailEntityManagerImpl] Mail Entity 16 has been created. 2021-03-13 16:42:30,691 http-nio-8080-exec-13 DEBUG [jira.emq.queue.MailEntityProcessorImpl] 1 mail items to be sent soon using queue 1 EMQ TEST project queue with "EMQ default" mailbox 2021-03-13 16:42:30,691 pool-66-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Mail Entity Processor Task has been created 2021-03-13 16:42:30,691 pool-66-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Waiting 10000 ms before more mail is sent 2021-03-13 16:42:30,692 pool-66-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Collected Mail Entity [id=16, qId=1, qName=EMQ TEST project queue with "EMQ default" mailbox] for delivery [type=IMMEDIATE] 2021-03-13 16:42:30,692 pool-66-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Waiting 10000 ms before more mail is sent

The mail is then sent a little while after

1 2 3 4 5 6 7 8 9 10 11 12 13 14 2021-03-13 16:42:40,692 pool-66-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] No new Mail Entities found 2021-03-13 16:42:40,692 pool-66-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Sending 1 collected Mail Entities 2021-03-13 16:42:40,695 pool-66-thread-1 DEBUG [jira.emq.queue.MailSenderJiraSMTPImpl] Starting to open connection 2021-03-13 16:42:40,707 pool-66-thread-1 DEBUG [jira.emq.queue.MailSenderJiraSMTPImpl] Connection [host:smtp.mailtrap.io, from: emq-default@blah.com] opened 2021-03-13 16:42:40,712 pool-66-thread-1 DEBUG [jira.emq.queue.MailQueueSenderImpl] 1 mail items to be sent NOW using queue 1: EMQ TEST project queue with "EMQ default" mailbox 2021-03-13 16:42:40,764 pool-66-thread-1 DEBUG [jira.emq.queue.AttachmentDownloaderImpl] Trying to download image from 'http://localhost:8080/images/mail/atlassian-email-logo.png' for inlining 2021-03-13 16:42:40,766 pool-66-thread-1 DEBUG [jira.emq.queue.MailQueueSenderImpl] Sleeping for 100 ms before sending a new email 2021-03-13 16:42:40,867 pool-66-thread-1 DEBUG [jira.emq.queue.MailQueueSenderImpl] Sending Mail Entity 16 using connection [qId=3, qName=EMQ default, qFrom=emq-default@blah.com] with actual msg from: jiradefault@blah.com 2021-03-13 16:42:42,276 pool-66-thread-1 DEBUG [jira.emq.queue.MailSenderJiraSMTPImpl] Message [from=jiradefault@blah.com, subject=(TEST-5) This is a starting email template, update as required] sent in 1408 ms 2021-03-13 16:42:42,283 pool-66-thread-1 DEBUG [jira.emq.queue.MailQueueSenderImpl] Sending Mail Entity 16 has been sent using connection [qId=3, qName=EMQ default, qFrom=emq-default@blah.com] with actual msg from: jiradefault@blah.com 2021-03-13 16:42:42,283 pool-66-thread-1 DEBUG [jira.emq.queue.MailSenderJiraSMTPImpl] Closing SMTP server session [id=null, host=smtp.mailtrap.io, user=edbb06bded0edb, defaultFrom=emq-default@blah.com] 2021-03-13 16:42:42,285 pool-66-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Waiting 10000 ms before more mail is sent 2021-03-13 16:42:52,285 pool-66-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] No new Mail Entities found 2021-03-13 16:42:52,285 pool-66-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Mail Entity Processor Task has finished

Immediate Delivery Auditing

The EMQ > Auditing > Mail Items then shows the mail sent by immediate delivery.

The drop-down, circled above, gives access details of the sent mail, it includes details of the queue, and the from: address that the message had.

In the report below, an empty “qFrom:” in the section means that no additional email was defined on the queue, and the default set in the Mail Connection would be used.

Received immediate delivery mail

We use mailtrap.io for lots of email testing, it allows a dead end SMTP mailbox to be delivered to (with any from/to detail) without actually delivering to real mailbox recipients, we can use it to verify delivery and details within the sent mails.

Mail source, showing (1) from: set by the API client, in this case, we can show it’s from JEMH (2).

 

Immediate Delivery with a nominated queueId

The ID of the EMQ Queue is not as visible as it could be, it can be found on the edit screen URL in the browser:

1 http://localhost:8080/plugins/servlet/emq/general-configuration#/mailConfiguration/mailQueue/2

Here we show an issue with a custom field containing the same queueId (1) and the custom from address that JEMH would use (2):

catch-22, for immediate delivery, setting the ‘custom from address custom field’ is only possible during edit when EMQ is not enabled - we typically expected Digesting delivery, here the JEMH Notification config is shown during edit without EMQ enabled (just to set this):

And in JEMH, that custom field selected in the JEMH Notification config (the name is shown during edit)

Log output showing how queueId “2” is fed into EMQ.

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 2021-03-13 17:59:31,116 http-nio-8080-exec-15 DEBUG [jira.emq.queue.EMQBootstrap] digestNotification() has event: TEST-5, queueId=2, subject: (TEST-5) This is a starting email template, update as required 2021-03-13 17:59:31,121 http-nio-8080-exec-15 DEBUG [jira.emq.queue.JiraServiceUtils] Email match [assignee@localhost] with [key=JIRAUSER10100,username=assignee, email=assignee@localhost] 2021-03-13 17:59:31,121 http-nio-8080-exec-15 DEBUG [jira.emq.queue.JiraServiceUtils] User assignee is active, getting directoryUser 2021-03-13 17:59:31,121 http-nio-8080-exec-15 DEBUG [jira.emq.queue.JiraServiceUtils] Got ACTIVE directory user: assignee, directoryId: 1 2021-03-13 17:59:31,130 http-nio-8080-exec-15 DEBUG [jira.emq.queue.ActionEvaluatorImpl] Action IMMEDIATE resolved for [username=assignee, email=assignee@localhost, userkey=JIRAUSER10100] 2021-03-13 17:59:31,142 http-nio-8080-exec-15 DEBUG [jira.emq.manager.MailEntityManagerImpl] Mail Entity 20 has been created. 2021-03-13 17:59:31,143 http-nio-8080-exec-15 DEBUG [jira.emq.queue.MailEntityProcessorImpl] 1 mail items to be sent soon using queue 2 Queue for TEST Project 2021-03-13 17:59:31,144 pool-84-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Mail Entity Processor Task has been created 2021-03-13 17:59:31,144 pool-84-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Waiting 10000 ms before more mail is sent 2021-03-13 17:59:31,144 pool-84-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Collected Mail Entity [id=20, qId=2, qName=Queue for TEST Project] for delivery [type=IMMEDIATE] 2021-03-13 17:59:31,145 pool-84-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Waiting 10000 ms before more mail is sent 2021-03-13 17:59:41,145 pool-84-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] No new Mail Entities found 2021-03-13 17:59:41,145 pool-84-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Sending 1 collected Mail Entities 2021-03-13 17:59:41,145 pool-84-thread-1 DEBUG [jira.emq.queue.MailSenderJiraSMTPImpl] Starting to open connection 2021-03-13 17:59:41,147 pool-84-thread-1 DEBUG [jira.emq.queue.MailSenderJiraSMTPImpl] Connection [host:smtp.mailtrap.io, from: emq2@blah.com] opened 2021-03-13 17:59:41,148 pool-84-thread-1 DEBUG [jira.emq.queue.MailQueueSenderImpl] 1 mail items to be sent NOW using queue 2: Queue for TEST Project 2021-03-13 17:59:41,166 pool-84-thread-1 DEBUG [jira.emq.queue.AttachmentDownloaderImpl] Trying to download image from 'http://localhost:8080/images/mail/atlassian-email-logo.png' for inlining 2021-03-13 17:59:41,168 pool-84-thread-1 DEBUG [jira.emq.queue.MailQueueSenderImpl] Sleeping for 100 ms before sending a new email 2021-03-13 17:59:41,268 pool-84-thread-1 DEBUG [jira.emq.queue.MailQueueSenderImpl] Sending Mail Entity 20 using connection [qId=2, qName=EMQ mailbox 2, qFrom=emq2@blah.com] with actual msg from: emq2@blah.com 2021-03-13 17:59:42,664 pool-84-thread-1 DEBUG [jira.emq.queue.MailSenderJiraSMTPImpl] Message [from=emq2@blah.com, subject=(TEST-5) This is a starting email template, update as required] sent in 1396 ms 2021-03-13 17:59:42,674 pool-84-thread-1 DEBUG [jira.emq.queue.MailQueueSenderImpl] Sending Mail Entity 20 has been sent using connection [qId=2, qName=EMQ mailbox 2, qFrom=emq2@blah.com] with actual msg from: emq2@blah.com 2021-03-13 17:59:42,674 pool-84-thread-1 DEBUG [jira.emq.queue.MailSenderJiraSMTPImpl] Closing SMTP server session [id=null, host=smtp.mailtrap.io, user=bc8b5b4f805e1c, defaultFrom=emq2@blah.com] 2021-03-13 17:59:42,677 pool-84-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Waiting 10000 ms before more mail is sent

The mail received:

The headers show that the from: address is the expected emq2@blah.com, defined in the issue custom field, so if the smtp account used considers this valid, it will be delivered!

 

Digested Delivery

The API digest path is similar to the Jira event path, we get an email, that's already rendered, so we pull the text/html content from the mail if its there, text/plain if not, and digest that.

The content is consumed:

1 2 3 4 5 6 7 2021-03-13 17:19:39,185 http-nio-8080-exec-22 DEBUG [jira.emq.queue.EMQBootstrap] digestNotification() for usable event: TEST-5, subject: (TEST-5) This is a starting email template, update as required 2021-03-13 17:19:39,187 http-nio-8080-exec-22 DEBUG [jira.emq.queue.QueueManagerImpl] Matched DEFAULT queue [EMQ TEST project queue with "EMQ default" mailbox] for event 6 on TEST-5 2021-03-13 17:19:39,193 http-nio-8080-exec-22 DEBUG [jira.emq.queue.JiraServiceUtils] Email match [assignee@localhost] with [key=JIRAUSER10100,username=assignee, email=assignee@localhost] 2021-03-13 17:19:39,193 http-nio-8080-exec-22 DEBUG [jira.emq.queue.JiraServiceUtils] User assignee is active, getting directoryUser 2021-03-13 17:19:39,193 http-nio-8080-exec-22 DEBUG [jira.emq.queue.JiraServiceUtils] Got ACTIVE directory user: assignee, directoryId: 1 2021-03-13 17:19:39,202 http-nio-8080-exec-22 DEBUG [jira.emq.queue.ActionEvaluatorImpl] Action DIGEST resolved for [username=assignee, email=assignee@localhost, userkey=JIRAUSER10100] 2021-03-13 17:19:39,215 http-nio-8080-exec-22 DEBUG [jira.emq.manager.DigestEntityManagerImpl] Digest Entity 20 has been created.

We can also see the API delivered content in EMQ > Auditing > Digest Items:

The EMQScheduledFlushJob kicks in to process digest entries:

1 2 3 4 5 2021-03-13 17:20:07,515 Caesium-1-2 DEBUG [service.scheduler.impl.PluginJobRunnerImpl] Running job type: EMQScheduledFlushJob 2021-03-13 17:20:07,515 Caesium-1-2 DEBUG [service.scheduler.jobs.EMQScheduledFlushJob] Flushing queues 2021-03-13 17:20:07,534 Caesium-1-2 DEBUG [jira.emq.queue.DigestEntityProcessorImpl] 1 Digest Entities will be processed now. 2021-03-13 17:20:07,544 Caesium-1-2 DEBUG [service.scheduler.jobs.EMQScheduledFlushJob] Next job scheduled for : Sat Mar 13 17:25:07 GMT 2021 2021-03-13 17:20:07,600 pool-73-thread-1 DEBUG [jira.emq.manager.MailEntityManagerImpl] Mail Entity 17 has been created.

Mail Items are generated by the job for delivery,

Again, the Report is accessed by the drop-down, circled above:

The EMQScheduledFlushJob kicks in to flush mail that has been queued:

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 2021-03-13 17:22:07,517 Caesium-1-2 DEBUG [service.scheduler.impl.PluginJobRunnerImpl] Running job type: EMQScheduledFlushJob 2021-03-13 17:22:07,523 Caesium-1-2 DEBUG [jira.emq.queue.MailEntityProcessorImpl] 1 mail items to be sent soon using queue 1 EMQ TEST project queue with "EMQ default" mailbox 2021-03-13 17:22:07,526 pool-75-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Mail Entity Processor Task has been created 2021-03-13 17:22:07,526 pool-75-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Polling for a new item without waiting. 2021-03-13 17:22:07,526 pool-75-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Collected Mail Entity [id=17, qId=1, qName=EMQ TEST project queue with "EMQ default" mailbox] for delivery [type=DIGESTED] 2021-03-13 17:22:07,526 pool-75-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Polling for a new item without waiting. 2021-03-13 17:22:07,526 pool-75-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] No new Mail Entities found 2021-03-13 17:22:07,526 pool-75-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Sending 1 collected Mail Entities 2021-03-13 17:22:07,528 pool-75-thread-1 DEBUG [jira.emq.queue.MailSenderJiraSMTPImpl] Starting to open connection 2021-03-13 17:22:07,540 pool-75-thread-1 DEBUG [jira.emq.queue.MailSenderJiraSMTPImpl] Connection [host:smtp.mailtrap.io, from: emq-default@blah.com] opened 2021-03-13 17:22:07,544 pool-75-thread-1 DEBUG [jira.emq.queue.MailQueueSenderImpl] 1 mail items to be sent NOW using queue 1: EMQ TEST project queue with "EMQ default" mailbox 2021-03-13 17:22:07,581 pool-75-thread-1 DEBUG [jira.emq.queue.AttachmentDownloaderImpl] Trying to download image from 'http://localhost:8080/secure/viewavatar?size=xsmall&avatarId=10318&avatarType=issuetype' for inlining 2021-03-13 17:22:07,587 pool-75-thread-1 DEBUG [jira.emq.queue.AttachmentDownloaderImpl] Trying to download image from 'http://localhost:8080/images/icons/priorities/medium.svg' for inlining 2021-03-13 17:22:07,608 pool-75-thread-1 DEBUG [jira.emq.queue.MailQueueSenderImpl] Sleeping for 100 ms before sending a new email 2021-03-13 17:22:07,708 pool-75-thread-1 DEBUG [jira.emq.queue.MailQueueSenderImpl] Sending Mail Entity 17 using connection [qId=3, qName=EMQ default, qFrom=emq-default@blah.com] with actual msg from: emq-default@blah.com 2021-03-13 17:22:09,106 pool-75-thread-1 DEBUG [jira.emq.queue.MailSenderJiraSMTPImpl] Message [from=emq-default@blah.com, subject=EMQ Issue Digest: EMQ TEST project queue with "EMQ default" mailbox - #1 - 13 Mar] sent in 1398 ms 2021-03-13 17:22:09,108 pool-75-thread-1 DEBUG [jira.emq.queue.MailQueueSenderImpl] Sending Mail Entity 17 has been sent using connection [qId=3, qName=EMQ default, qFrom=emq-default@blah.com] with actual msg from: emq-default@blah.com 2021-03-13 17:22:09,108 pool-75-thread-1 DEBUG [jira.emq.queue.MailSenderJiraSMTPImpl] Closing SMTP server session [id=null, host=smtp.mailtrap.io, user=edbb06bded0edb, defaultFrom=emq-default@blah.com] 2021-03-13 17:22:09,109 pool-75-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Polling for a new item without waiting. 2021-03-13 17:22:09,109 pool-75-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] No new Mail Entities found 2021-03-13 17:22:09,109 pool-75-thread-1 DEBUG [jira.emq.queue.MailEntityProcessorImpl] Mail Entity Processor Task has finished 2021-03-13 17:22:13,940 Caesium-1-4 DEBUG [service.scheduler.impl.PluginJobRunnerImpl] Running job type: EMQFlushMonitorJob 2021-03-13 17:22:13,941 Caesium-1-4 DEBUG [service.scheduler.jobs.EMQFlushMonitorJob] Flush Monitor job running 2021-03-13 17:22:13,942 Caesium-1-4 DEBUG [service.scheduler.impl.PluginScheduleManagerImpl] Job[EMQScheduledFlushJob] is OK and has yet to run, next run: Sat Mar 13 17:24:07 GMT 2021 2021-03-13 17:22:13,942 Caesium-1-4 INFO [service.scheduler.jobs.EMQFlushMonitorJob] [Jira Server] will test for IMMEDS 2021-03-13 17:22:13,944 Caesium-1-4 DEBUG [service.scheduler.jobs.EMQFlushMonitorJob] [Jira SERVER] No unsent IMMEDIATE delivery messages found

The EMQ > Auditing > Digest History shows the 17:22 flush: