Skip to end of metadata
Go to start of metadata

You are viewing an old version of this page. View the current version.

Compare with Current View Page History

« Previous Version 4 Next »

(warning) INTERNAL ONLY (warning)

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

Lifecycle

Installation

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

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

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

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

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

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!

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.

Immediate Delivery

The unhappy path of a different mail from: address to the queue from: default

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:

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.

Digested Delivery

  • No labels