Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Change Slack unmarshalling error from error to warning level #619

Closed
bygui86 opened this issue Jun 15, 2022 · 12 comments · Fixed by #629
Closed

Change Slack unmarshalling error from error to warning level #619

bygui86 opened this issue Jun 15, 2022 · 12 comments · Fixed by #629
Assignees
Labels
bug Something isn't working slack
Milestone

Comments

@bygui86
Copy link

bygui86 commented Jun 15, 2022

Describe the bug
I configured BotKube to send messages over Slack. BotKube app is installed in Slack workspace, I receive messages in different channels, everything work fine. But in the BotKube logs I see tons of "Slack unmarshalling error: RTM Error: Received unmapped event "user_status_changed"" messages like this

ERRO[2022-06-15T11:30:02Z] Slack unmarshalling error: RTM Error: Received unmapped event "user_status_changed": {"type":"user_status_changed","user":{"id":"***","team_id":"***","name":"jdoe","deleted":false,"color":"bc3663","real_name":"John Doe","tz":"Europe\/Amsterdam","tz_label":"Central European Summer Time","tz_offset":7200,"profile":{"title":"","phone":"","skype":"","real_name":"John Doe","real_name_normalized":"John Doe","display_name":"John","display_name_normalized":"John","fields":{},"status_text":"In a meeting","status_emoji":":spiral_calendar_pad:","status_emoji_display_info":[],"status_expiration":1655296200,"avatar_hash":"effbe98e0c63","image_original":"***original.jpg","is_custom_image":true,"email":"[email protected]","huddle_state":"default_unset","huddle_state_expiration_ts":0,"first_name":"John","last_name":"Doe","image_24":"***_24.jpg","image_32":"***_32.jpg","image_48":"***_48.jpg","image_72":"***_72.jpg","image_192":"***_192.jpg","image_512":"***_512.jpg","image_1024":"***_1024.jpg","status_text_canonical":"","team":"***"},"is_admin":false,"is_owner":false,"is_primary_owner":false,"is_restricted":false,"is_ultra_restricted":false,"is_bot":false,"is_app_user":false,"updated":1655292601,"is_email_confirmed":true,"who_can_share_contact_card":"EVERYONE","locale":"en-US"},"cache_ts":1655292601,"event_ts":"1655292602.019400"}

BotKube configuration

apiVersion: v1
kind: ConfigMap
metadata:
  name: botkube
data:
  resource_config.yaml: |
    resources:
      - name: v1/nodes
        namespaces:
          include:
            - all
        events:
          - create
          - delete
          - update
      - name: v1/namespaces
        namespaces:
          include:
            - all
        events:
          - all
      # ... some others ...
    recommendations: false
    settings:
      configwatcher: false
      upgradeNotifier: true
      clustername: ceiba-test
      kubectl:
        enabled: false
        restrictAccess: true
        defaultNamespace: botkube
        commands:
          verbs:
            - "get"
            - "describe"
            - "logs"
          resources:
            - "namespaces"
            - "deployments"
            - "statefulsets"
            - "daemonsets"
            - "pods"
            - "services"
            - "cronjobs"
            - "jobs"
            - "configmaps"
            - "persistentvolumeclaims"

To Reproduce
Steps to reproduce the behavior:

  1. Install BotKube app in Slack workspace
  2. Configure BotKube with Slack values
  3. Deploy BotKube in k8s in "botkube" namespace
  4. Watching BotKube logs

Expected behavior
BotKube should ignore such messages without logging as error or directly not receiving such messages.

Additional context
K8s provider: GCP/GKE
K8s version: v1.21.11-gke.900
BotKube version: v0.12.4

@bygui86 bygui86 added the bug Something isn't working label Jun 15, 2022
@mszostok
Copy link
Contributor

mszostok commented Jun 15, 2022

Hi @bygui86, thanks for reporting that. FYI: it duplicates #579

And it was addressed already in #610 and sensitive data is not printed to logs (see: slack-go/slack#1067).

AFAIK with the current library we are not able to ignore certain events. We get all of them, right @pkosiec?
However, in the long term, it will be good to investigate it further and subscribe to only those events that we need.


BotKube should ignore such messages without logging as error

Unfortunately, it's a generic *slack.UnmarshallingErrorEvent error, so if we will ignore it totally, in some cases, debugging can be more complicated. WDYT @pkosiec?

@mszostok mszostok added the duplicate This issue or pull request already exists label Jun 15, 2022
@pkosiec
Copy link
Member

pkosiec commented Jun 15, 2022

I agree, this is something related to how the library works. What we can think about is changing the log level from error to warning or something like this 🤔https://github.com/infracloudio/botkube/blob/develop/pkg/bot/slack.go#L141-L142

But as you wrote @mszostok, the issue with printing sensitive data is already resolved.

@mszostok mszostok added this to the v0.13.0 milestone Jun 15, 2022
@mszostok
Copy link
Contributor

So I added this issue for v0.13.0 to change the level from error to warning.

@mszostok mszostok changed the title [BUG] Slack unmarshalling error - RTM Error - Received unmapped event "user_status_changed" Change Slack unmarshalling error from error to warning level Jun 15, 2022
@mszostok mszostok added slack and removed duplicate This issue or pull request already exists labels Jun 15, 2022
@bygui86
Copy link
Author

bygui86 commented Jun 15, 2022

@mszostok thanks for your answer and sorry for the possible duplication, I missed that issue. But actually my point is a bit different...
As BotKube is not supposed to care about Slack "user_status_changed" events, I think we can totally avoid to print out related errors.
In the line pointed by @pkosiec (https://github.com/infracloudio/botkube/blob/develop/pkg/bot/slack.go#L141-L142) we can add a simple if close checking the content of the error message and avoiding to log if a "user_status_changed" event was received (e.g. same as https://github.com/infracloudio/botkube/blob/develop/pkg/bot/slack.go#L110-L114)
Something like:

# ...
			case *slack.UnmarshallingErrorEvent:
				if ! strings.Contains(ev.Error(), "user_status_changed") {
					b.log.Errorf("Slack unmarshalling error: %+v", ev.Error())
				}
# ...

It would be a nice improvements, since I see such log line really often!

@bygui86
Copy link
Author

bygui86 commented Jun 15, 2022

So I added this issue for v0.13.0 to change the level from error to warning.

@mszostok sorry but changing the log level won't solve anything... in the logs I will see anyway such line...
Right above I suggested how to avoid printing that specific kind of message...

@mszostok
Copy link
Contributor

mszostok commented Jun 15, 2022

@mszostok sorry but changing the log level won't solve anything... in the logs I will see anyway such line...

I understand, however, you can change the log level with LOG_LEVEL and print errors only. It's OK, as in production you are interested only in errors. For developing or debugging, it's good to have more information.


The solution you mentioned is OK as a workaround, but it's too error-prone to maintain that. It's not a good practice to assert the error message, as it's meant for humans. We cannot expect how this will work in the future release of slack-go lib.

The best option is to subscribe to required events only.

The other option is to cast the slack.UnmarshallingErrorEvent to EventsAPIEvent and assert Type field. But we will need to have a list with all possible events that are sent by Slack as user_status_changed is not the only one, e.g.:

Personally, I will vote for checking whether there is an option to subscribe to required events only. If not possible, check if we can contribute such support to slack-go lib (only if it's not too complicated and won't take too long). Otherwise, I would leave it as it is and log it as warning.

@pkosiec
Copy link
Member

pkosiec commented Jun 17, 2022

I will vote for checking whether there is an option to subscribe to required events only. If not possible, check if we can contribute such support to slack-go lib (only if it's not too complicated and won't take too long).

That's something beyond slack-go library. It is configured on the Slack app side (BotKube app installed from Slack app directory) - https://api.slack.com/apis/connections/events-api. Probably right now the BotKube Slack app is configured to receive all possible events, and we can narrow the list down.

Anyway, I also think it will be the best to keep this event logged, but with different level 👍

@bygui86
Copy link
Author

bygui86 commented Jun 21, 2022

The solution you mentioned is OK as a workaround, but it's too error-prone to maintain that. It's not a good practice to assert the error message, as it's meant for humans. We cannot expect how this will work in the future release of slack-go lib.
The best option is to subscribe to required events only.

@mszostok yeah you are right, it would be way better to subscribe to required events only.

That's something beyond slack-go library. It is configured on the Slack app side (BotKube app installed from Slack app directory) - https://api.slack.com/apis/connections/events-api. Probably right now the BotKube Slack app is configured to receive all possible events, and we can narrow the list down.

@pkosiec thanks for suggestion, I check asap!

@bygui86
Copy link
Author

bygui86 commented Jun 21, 2022

@pkosiec sorry I thought you were referring to a specific configuration of BotKube app installation in our Slack workspace, but I don't find anything. Are you talking about BotKube app implementation itself?

@pkosiec
Copy link
Member

pkosiec commented Jun 30, 2022

Sorry @bygui86, somehow I missed your message. What I meant is the BotKube Slack app from the Slack App directory: https://slack.com/apps/AF5DZLHPC-botkube?tab=more_info

So, unfortunately it is not about a specific Slack app installation (which you do by "Add to Slack" button), but rather the global configuration. We'll need to look into that if we can narrow it down, but in the meantime we will change the level of these log messages. Stay tuned for updates!

@bygui86
Copy link
Author

bygui86 commented Jun 30, 2022

@pkosiec thanks for the clarification!
thanks and keep us posted :)

@mszostok mszostok self-assigned this Jun 30, 2022
mergify bot pushed a commit that referenced this issue Jul 4, 2022
##### SUMMARY

This PR only decreases the unmarshall error severity from err to warn. To make it a bit better, we can contribute to the `slack` lib and replace:
```go
err := fmt.Errorf("RTM Error: Received unmapped event %q", typeStr)
```
_([source](https://github.com/slack-go/slack/blob/1dcd0d459a30d8402f5c0c42e20df80b56dac5e3/websocket_managed_conn.go#L477))_

with error type `UnmappedError`. This won't be a breaking change for them, so we should be able to merge that.
As a result, we will know the details about the error and could implement sth like:

```go
// handlingEvents holds event names which have corresponding handling logic.
var handlingEvents = sets.NewString("message", "connected")

// trimmed

      case *slack.UnmarshallingErrorEvent:
        err, ok := ev.ErrorObj.(slack.UnmappedError)
        if ok && !handlingEvents.Has(err.EventType()) { // it's not an err for us, as we don't care about this event type.
          b.log.Debugf("Slack unmarshalling error: %+v", ev.Error())
          continue
        }

        b.log.Errorf("Slack unmarshalling error: %+v", ev.Error())
```

In that way even if someone will configure custom Slack bot with wrong event subscription we will be able to “ignore them”.

WDYT? Is it worth it? If we stay with RTM, then it's the only option.

##### FINDINGS

I wanted to describe the workaround for this issue by creating the own Bot. I found that the current Bot is based on RTM. This means that it issues the [old API](https://api.slack.com/rtm).
![Screen Shot 2022-07-04 at 12 36 47](https://user-images.githubusercontent.com/17568639/177138030-04870c01-32aa-45ac-adb2-8bb05d542622.png)

In this case, we are not able to:
- reduce the app permission 
- select events to which we want to be subscribed

The best option would be changing the implementation from RTM to [WebSocket mode](https://api.slack.com/apis/connections/socket). Should I  create an issue?

Related issue:
- #619
@mszostok
Copy link
Contributor

mszostok commented Jul 4, 2022

After doing my investigation I realized that it won't be as easy as described, first we need to do the migration, please see and follow dedicated issue for that: #631

The alternative workaround was described in the PR #629, so I will create a dedicated PR against slack lib and see whether they will accept it or not (slack-go/slack#1086).

@mszostok mszostok closed this as completed Jul 4, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working slack
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants