Troubleshooting with the EMQ logfile
- Andy Brook [Plugin People]
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: EMQScheduledFlushJobThis 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: EMQScheduledFlushJobThis 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
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
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
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!
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.
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.
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:
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
The mail is then sent a little while after
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:
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.
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:
We can also see the API delivered content in EMQ > Auditing > Digest Items:
The EMQScheduledFlushJob kicks in to process digest entries:
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:
The EMQ > Auditing > Digest History shows the 17:22 flush: