Slack Log Settings - Only one log level?

jflores13

Hello, dear IAS devs.

We are using Slack for our alerts and, for dev purposes, we wanted sepparate channels for the different log levels.

I don't know if we're missing out on something, but my question is, what if we wanted to send different log levels to different channels? Is this possible?

Via the System Settings UI, there doesn't seem to be an option to do this, but through my Mango learning curve I've found out multiple times that I'm just looking for stuff in the wrong place. Hope this is also the case.

Thanks in advance!
Greetings.

CraigWeb

Hi @jflores13

This is not possible with the slack log publisher.

terrypacker

@jflores13 as @CraigWeb said this isn't possible with just the log publisher but it does seem like a useful feature. The log message posting feature was more of a proof of concept that I put together to test out the Slack API. If there is enough demand for this I could see us adding a few more features such as:

Select the channel for the log message level
Define templates for the message format
Execute a script to format the message before it is sent

I did some light searching in Slack and found that you might be able to use this app to forward messages to other channels. https://slack.com/intl/en-pt/help/articles/360000482666-copy-messages-to-another-channel-instantly I think in order to do it this way you would need a way to customize the message being sent by Mango (which is not possible yet).

After thinking about this more I believe you could use the LOG4J data source with an event detector which would raise events that could be handled by Slack Event Handlers. This would work as follows:

Create Log4J data source with data points for the various LOG levels you want to send to slack
Add an on change event detector to each point.
Add a Slack event handler to each detector to publish the event message to the channel.

The resulting message will be different than the one sent from the Log publisher but it may be good enough for what you are doing.

Note that I just released a new version of this module for Mango 3.6 as while I was testing this I found a bug and also realized that it did not post the latest value of the point in the event message (which it does now).

jflores13

Hello,

@craigweb said in Slack Log Settings - Only one log level?:

Hi @jflores13
This is not possible with the slack log publisher.

Alright, thanks, @CraigWeb.

@terrypacker said in Slack Log Settings - Only one log level?:

After thinking about this more I believe you could use the LOG4J data source with an event detector which would raise events that could be handled by Slack Event Handlers. This would work as follows:

Create Log4J data source with data points for the various LOG levels you want to send to slack

Add an on change event detector to each point.

Add a Slack event handler to each detector to publish the event message to the channel.

Note that I just released a new version of this module for Mango 3.6 as while I was testing this I found a bug and also realized that it did not post the latest value of the point in the event message (which it does now).

Wow, @terrypacker, thanks for taking the time to think it through and to investigate. We will definitely try this LOG4J approach.

We actually noticed strange behaviour before, because when we changed the log level to Information, the messages we started getting were empty, but we thought we were doing something wrong. Today, we updated the module at 13:52. We got the info messages of the startup and modules loading correctly now, but right after, the extreme error messages started coming. This is the error message copied from our Slack channel:

ERROR 2019-23-10T16:31:51.825  (com.ullink.slack.simpleslackapi.impl.SlackWebSocketSessionImpl.connectImpl:337) - Error during authentication : ratelimited

This same error was sent 4,050 times from 13:53 to 14:17, then it suddenly stopped. We then decided to add a module to test if it happened again, and it did. When Mango restarted, we got 3,626 error messages from 16:08 to 16:31. Apparently, all of them are the same error.

I looked that up in Slack and found out about the rate limits, and the raw HTTP response that you get when you hit the limits. Apparently, you get an HTTP 429 Too Many Requests error. According to Slack, the raw response could look like this:

HTTP/1.1 429 Too Many Requests
Retry-After: 30

I'm thinking that the handling of this Retry-After header probably has something to do with this, am I wrong?

Thanks again!
Greetings!

terrypacker

@jflores13 it looks to me like there is a logging loop I didn't consider when I coded this up. I specifically avoided using any logging statements in the logic of sending the message to slack that I wrote, but I failed to consider that they library I was using would also perform logging. Basically your system entered into a loop where it is rate limited and logs that message, which causes Mango to attempt to send another message via Slack that is again rate limited and so on and so forth.

I'm not going to fix it in the code for now but you can avoid this by turning off logging for the Slack library. You may still get rate limited as that is not something that was implemented for this module. To turn off logging add this to the log4j2.xml file in Mango and restart it.

<AsyncLogger includeLocation="true" name="com.ullink.slack.simpleslackapi" level="none"/>

I would strongly suggest that you look at the Log4J data source approach as that will also allow you to use regex to match the log messages you want to receive and help avoid the rate limiting problem.

@jflores13 said in Slack Log Settings - Only one log level?:

I'm thinking that the handling of this Retry-After header probably has something to do with this, am I wrong?

That would be a good feature for this module to have, a way to queue and then retry messages that have been rejected for rate limiting reasons. This thread will be a good reference if/when we can get enough support to do more development on this module. I could be persuaded to create a public fork of the Slack module if anyone wants to make some changes and submit a pull request...

jflores13

@terrypacker ahhh, I see! Alright, don't worry, thanks for that quick fix, I will definitely try the Log4J approach.

@terrypacker said in Slack Log Settings - Only one log level?:

That would be a good feature for this module to have, a way to queue and then retry messages that have been rejected for rate limiting reasons. This thread will be a good reference if/when we can get enough support to do more development on this module. I could be persuaded to create a public fork of the Slack module if anyone wants to make some changes and submit a pull request...

I would love to contribute but, to be honest, I don't think my coding skills are enough for that yet. I'll keep learning and hopefully I can persuade you soon.

Thanks again, Terry! :)

jflores13

@terrypacker Just finished configuring the Log4j approach and you were absolutely right, it's perfect for what we wanted. Works well too.

Thanks a lot!

jflores13

Oh well, I'm sorry but I take it back, seems like we can't stop the loop, even with the Log4j approach we are still getting thousands of events. More than 24,000 in a couple of hours. Most of them are like this:

ERROR 2019-10-29T11:44:19,621 (com.infiniteautomation.mango.slack.event.SlackMessageEventHandlerRT.postMessage:145) - Slack message failed to send java.net.ConnectException: ratelimited at com.ullink.slack.simpleslackapi.impl.SlackWebSocketSessionImpl.connectImpl(SlackWebSocketSessionImpl.java:338) ~[?:?] at com.ullink.slack.simpleslackapi.impl.SlackWebSocketSessionImpl.connect(SlackWebSocketSessionImpl.java:292) ~[?:?] at com.infiniteautomation.mango.slack.event.SlackMessageEventHandlerRT.postMessage(SlackMessageEventHandlerRT.java:122) ~[?:?] at com.infiniteautomation.mango.slack.event.SlackMessageEventHandlerRT.eventRaised(SlackMessageEventHandlerRT.java:67) ~[?:?] at com.serotonin.m2m2.rt.EventManagerImpl.handleRaiseEvent(EventManagerImpl.java:1048) ~[mango-3.6.4.jar:?] at com.serotonin.m2m2.rt.EventManagerImpl.raiseEvent(EventManagerImpl.java:243) ~[mango-3.6.4.jar:?] at com.serotonin.m2m2.rt.event.detectors.PointEventDetectorRT.raiseEvent(PointEventDetectorRT.java:43) ~[mango-3.6.4.jar:?] at com.serotonin.m2m2.rt.event.detectors.PointChangeDetectorRT.pointChanged(PointChangeDetectorRT.java:54) ~[mango-3.6.4.jar:?] at com.serotonin.m2m2.rt.dataImage.DataPointRT$EventNotifyWorkItem.execute(DataPointRT.java:817) ~[mango-3.6.4.jar:?] at com.serotonin.m2m2.rt.maint.BackgroundProcessingImpl$RejectableWorkItemRunnable.run(BackgroundProcessingImpl.java:632) ~[mango-3.6.4.jar:?] at com.serotonin.timer.Task.runTask(Task.java:179) ~[mango-3.6.4.jar:?] at com.serotonin.timer.TaskWrapper.run(TaskWrapper.java:23) ~[mango-3.6.4.jar:?] at com.serotonin.timer.OrderedThreadPoolExecutor$OrderedTaskCollection.run(OrderedThreadPoolExecutor.java:336) ~[mango-3.6.4.jar:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_172] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_172] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_172]

Couldn't find out what is triggering these changes that raise the event detector.

Tried turning off the "Error" data point but now the "Warning" one is also sending weird messages, like this one:

WARN 2019-10-29T12:01:45,429 (com.serotonin.m2m2.web.dwr.MiscDwr.jsError:167) - Javascript error Description: Error: Tried to register widget with id==chartRendererSelect but that id is already registered Page: http://192.168.100.33:8088/resources/dojo/dojo.js?v=1571864830 line 345 > Function line 3 > eval Line: 2 Browser name: Firefox Browser version: 71 osName: Windows location: http://192.168.100.33:8088/data_source_edit.shtm?dsid=498 @ Oct 29, 2019 12:01 PM

We are getting this message when we try to edit the Log4j data points in the old UI (so we can access the event detectors and the purge now button). Explanation below:

Strangely, when we try to edit the data source in the old UI, the "Data points" tab is not existent inside the data source. So I look for the points in the global "Data points" tab, where all data points appear, I filter them by name to find the Log4j Slack Messages Data Points, but most times, when I click the edit (pencil) button on any of the 4 data points, I only get the above "Warning" message in Slack and this same message on a blue box in the old UI:

Error: Tried to register widget with id==chartRendererSelect but that id is already registered

It works super randomly; I seldom get to edit the data point. It's a strange behaviour, something I never saw before with any other data source. I did add the line @terrypacker suggested in the log4j2.xml, inside the loggers section, and restarted it btw.

Is there a quick fix to this? Thanks!