Failed to fetch users by their IDs: internal_error

[caywin25]

Hello,

Thank you for your job. I'am testing irc-slack but when I want to connect on my slack team, I have this error in irssi :

Failed to fetch users in channel ` (channel ID: XXXXXXX): Failed to fetch users by their IDs: Post "https://slack.com/api/users.info": connection error: PROTOCOL_ERROR

Could you help me please ? Thank you

[insomniacslk]

This seems to come from net/http (https://github.com/golang/go/blob/master/src/net/http/h2_bundle.go#L1114) and from a quick look at that file it seems something went wrong in the HTTP communication between irc-slack and the Slack API service. Do you see this problem with other API calls too? Can you reproduce this consistently, or is it intermittent?

[rodarima]

This problem seems to be caused by the slack-go library attempting to include a long list of users in the user field, which the current API doc only specifies one.

Here is more info:

% GODEBUG=http2debug=2 ./irc-slack -D -L debug

...
[2021-07-08T23:31:17+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][347] ircslack: Fetched 46 user IDs for channel XXXX (fetched so far: 46)
[2021-07-08T23:31:17+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][347] ircslack: Retrieving user information for 46 users
[2021-07-08T23:31:17+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][347] ircslack: Fetching information for 38 users out of 46 (8 already in cache)
[2021-07-08T23:31:17+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][347] ircslack: Fetching 38 users of 46, attempt 1 of 3
2021/07/08 23:31:17 http2: Transport encoding header ":authority" = "slack.com"
2021/07/08 23:31:17 http2: Transport encoding header ":method" = "POST"
2021/07/08 23:31:17 http2: Transport encoding header ":path" = "/api/users.info"
2021/07/08 23:31:17 http2: Transport encoding header ":scheme" = "https"
2021/07/08 23:31:17 http2: Transport encoding header "content-type" = "application/x-www-form-urlencoded"
2021/07/08 23:31:17 http2: Transport encoding header "content-length" = "576"
2021/07/08 23:31:17 http2: Transport encoding header "accept-encoding" = "gzip"
2021/07/08 23:31:17 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2021/07/08 23:31:17 http2: Framer 0xc00027c7e0: wrote HEADERS flags=END_HEADERS stream=13 len=12
2021/07/08 23:31:17 http2: Framer 0xc00027c7e0: wrote DATA flags=END_STREAM stream=13 len=576 data="include_locale=true&token=XXXXX&users=UXXXX%2CUXXXXX%2CU..." (320 bytes omitted)
2021/07/08 23:31:17 http2: Framer 0xc00027c7e0: read WINDOW_UPDATE stream=13 len=4 incr=576
2021/07/08 23:31:17 http2: Transport received WINDOW_UPDATE stream=13 len=4 incr=576
2021/07/08 23:31:17 http2: Framer 0xc00027c7e0: read WINDOW_UPDATE len=4 (conn) incr=576
2021/07/08 23:31:17 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=576
2021/07/08 23:31:17 http2: Framer 0xc00027c7e0: read HEADERS flags=END_HEADERS stream=13 len=1040
2021/07/08 23:31:17 http2: decoded hpack field header field ":status" = "200"
2021/07/08 23:31:17 http2: decoded hpack field header field "date" = "Thu, 08 Jul 2021 21:31:17 GMT"
2021/07/08 23:31:17 http2: decoded hpack field header field "server" = "Apache"
2021/07/08 23:31:17 http2: decoded hpack field header field "x-xss-protection" = "0"
2021/07/08 23:31:17 http2: decoded hpack field header field "pragma" = "no-cache"
2021/07/08 23:31:17 http2: decoded hpack field header field "cache-control" = "private, no-cache, no-store, must-revalidate"
2021/07/08 23:31:17 http2: decoded hpack field header field "access-control-allow-origin" = "*"
2021/07/08 23:31:17 http2: decoded hpack field header field "strict-transport-security" = "max-age=31536000; includeSubDomains; preload"
2021/07/08 23:31:17 http2: decoded hpack field header field "x-slack-req-id" = "xxxxxxxxxxx"
2021/07/08 23:31:17 http2: decoded hpack field header field "x-content-type-options" = "nosniff"
2021/07/08 23:31:17 http2: decoded hpack field header field "referrer-policy" = "no-referrer"
2021/07/08 23:31:17 http2: decoded hpack field header field "access-control-expose-headers" = "x-slack-req-id, retry-after"
2021/07/08 23:31:17 http2: decoded hpack field header field "x-slack-backend" = "r"
2021/07/08 23:31:17 http2: decoded hpack field header field "x-oauth-scopes" = "read,client,identify,post,apps"
2021/07/08 23:31:17 http2: decoded hpack field header field "x-accepted-oauth-scopes" = "users:read,read"
2021/07/08 23:31:17 http2: decoded hpack field header field "expires" = "Mon, 26 Jul 1997 05:00:00 GMT"
2021/07/08 23:31:17 http2: decoded hpack field header field "vary" = "Accept-Encoding"
2021/07/08 23:31:17 http2: decoded hpack field header field "access-control-allow-headers" = "slack-route, x-slack-version-ts, x-b3-traceid, x-b3-spanid, x-b3-parentspanid, x-b3-sampled, x-b3-flags"
2021/07/08 23:31:17 http2: decoded hpack field header field "content-encoding" = "gzip"
2021/07/08 23:31:17 http2: decoded hpack field header field "content-length" = "53"
2021/07/08 23:31:17 http2: decoded hpack field header field "content-type" = "application/json; charset=utf-8"
2021/07/08 23:31:17 http2: decoded hpack field header field "x-envoy-upstream-service-time" = "15"
2021/07/08 23:31:17 http2: decoded hpack field header field "x-backend" = "main_normal main_bedrock_normal_with_overflow main_canary_with_overflow main_bedrock_canary_with_overflow main_control_with_overflow main_bedrock_control_with_overflow"
2021/07/08 23:31:17 http2: decoded hpack field header field "x-server" = "slack-www-hhvm-main-iad-e7qm"
2021/07/08 23:31:17 http2: decoded hpack field header field "x-via" = "envoy-www-iad-vgrg, haproxy-edge-fra-i1bb"
2021/07/08 23:31:17 http2: decoded hpack field header field "x-slack-shared-secret-outcome" = "shared-secret"
2021/07/08 23:31:17 http2: decoded hpack field header field "via" = "envoy-www-iad-vgrg"
2021/07/08 23:31:17 http2: Transport received HEADERS flags=END_HEADERS stream=13 len=1040
2021/07/08 23:31:17 http2: Framer 0xc00027c7e0: read DATA stream=13 len=53 data="\x1f\x8b\b\x00\x00\x00\x00\x00\x00\x03\xabV\xca\xcfV\xb2JK\xcc)N\xd5QJ-*\xca/R\xb2R\xca\xcc+I-\xcaK̉\x87\b\xd4\x02\x00U\xae\xe4\xbf%\x00\x00\x00"
2021/07/08 23:31:17 http2: Transport received DATA stream=13 len=53 data="\x1f\x8b\b\x00\x00\x00\x00\x00\x00\x03\xabV\xca\xcfV\xb2JK\xcc)N\xd5QJ-*\xca/R\xb2R\xca\xcc+I-\xcaK̉\x87\b\xd4\x02\x00U\xae\xe4\xbf%\x00\x00\x00"
2021/07/08 23:31:17 http2: Framer 0xc00027c7e0: read DATA flags=END_STREAM stream=13 len=0 data=""
2021/07/08 23:31:17 http2: Transport received DATA flags=END_STREAM stream=13 len=0 data=""
[2021-07-08T23:31:17+02:00]  WARN ircslack: Sending ERR_UNKNOWNERROR (400) to client with message: Failed to fetch users in channel `general (channel ID: XXXXXX): Failed to fetch users by their IDs: internal_error
[2021-07-08T23:31:17+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][347] ircslack: Sending numeric reply: :localhost 400 xxxxxx :Failed to fetch users in channel `general (channel ID: XXXXXX): Failed to fetch users by their IDs: internal_error

[2021-07-08T23:31:17+02:00]  WARN ircslack: Cannot connect to Slack: Failed to fetch users in channel `general (channel ID: XXXXXX): Failed to fetch users by their IDs: internal_error
[2021-07-08T23:31:17+02:00]  WARN ircslack: Error handling connection from 127.0.0.1:59052: read tcp 127.0.0.1:6666->127.0.0.1:59052: use of closed network connection

Here is the data in plain text:

% echo "\x1f\x8b\b\x00\x00\x00\x00\x00\x00\x03\xabV\xca\xcfV\xb2JK\xcc)N\xd5QJ-*\xca/R\xb2R\xca\xcc+I-\xcaK<0309>\x87\b\xd4\x02\x00U\xae\xe4\xbf%\x00\x00\x00" | gunzip | hexdump -C

gzip: stdin: unexpected end of file
00000000  7b 22 6f 6b 22 3a 66 61  6c 73 65 2c 22 65 72 72  |{"ok":false,"err|
00000010  6f 72 22 3a 22 69 6e 74  65 72 6e 61 6c 5f 65 72  |or":"internal_er|
00000020  72 6f 72 22 7d                                    |ror"}|
00000025

Reducing the number of users fetched at the same time to 30 seems to work fine. Bigger chunk sizes return the internal error always.