emas80 commented 4 years ago

341 # Your checklist for this issue

[ X ] Jenkins version: 2.235.2 - 2.235.5
[ X ] Plugin version: v2.40 - v2.41

Description

It's been a few days the notification plugin stopped working. Checking the logs I can see

2020-09-08 08:21:01.639+0000 [id=11]    WARNING j.p.slack.StandardSlackService#postToSlack: Slack post may have failed. Response: null
2020-09-08 08:21:01.639+0000 [id=11]    WARNING j.p.slack.StandardSlackService#postToSlack: Response Code: 302

We haven't modified anything on Jenkins, on the plugin configuration or on Slack to justify that.

I've tried upgrading Jenkins, upgrading the plugin, creating a new integration, regenerating the token. I've also done all of that on a brand new Jenkins installation, starting from scratch.

I see this has been reported a few days before it started happening for us: https://issues.jenkins-ci.org/browse/JENKINS-63546?jql=project%20%3D%20JENKINS%20AND%20component%20%3D%20slack-plugin

Is it possible that something has changed internally to Slack that they are slowly rolling out to all the accounts?

timja commented 4 years ago

Can you add more logging please: It should make it clearer https://github.com/jenkinsci/slack-plugin#enable-additional-logging

emas80 commented 4 years ago

It does not seem to add much:

Sep 08, 2020 10:28:16 AM FINE jenkins.plugins.slack.StandardSlackService

Posting: to #MY-CHANNEL on faceit:  {"attachments":[{"fallback":"Slack/Jenkins plugin: you're all set on https://MY-JENKINS-URL/","color":"good","fields":[{"short":false,"value":"Slack/Jenkins plugin: you're all set on https://MY-JENKINS-URL/"}],"mrkdwn_in":["pretext","text","fields"]}],"link_names":"1","unfurl_links":"true","unfurl_media":"true","channel":"#MY-CHANNEL","as_user":"true"}

Sep 08, 2020 10:28:16 AM WARNING jenkins.plugins.slack.StandardSlackService postToSlack

Slack post may have failed. Response: null

Sep 08, 2020 10:28:16 AM WARNING jenkins.plugins.slack.StandardSlackService postToSlack

Response Code: 302

Sep 08, 2020 10:29:20 AM FINE jenkins.plugins.slack.StandardSlackService

Posting: to #MY-CHANNEL on faceit:  {"attachments":[{"fallback":"Slack/Jenkins plugin: you're all set on https://MY-JENKINS-URL/","color":"good","fields":[{"short":false,"value":"Slack/Jenkins plugin: you're all set on https://MY-JENKINS-URL/"}],"mrkdwn_in":["pretext","text","fields"]}],"link_names":"1","unfurl_links":"true","unfurl_media":"true","channel":"#MY-CHANNEL","as_user":"true"}

Sep 08, 2020 10:29:20 AM WARNING jenkins.plugins.slack.StandardSlackService postToSlack

Slack post may have failed. Response: null

Sep 08, 2020 10:29:20 AM WARNING jenkins.plugins.slack.StandardSlackService postToSlack

Response Code: 302

Sep 08, 2020 10:33:21 AM FINE jenkins.plugins.slack.StandardSlackService

Posting: to complete-wrong-channel on faceit:  {"attachments":[{"fallback":"Slack/Jenkins plugin: you're all set on https://MY-JENKINS-URL/","color":"good","fields":[{"short":false,"value":"Slack/Jenkins plugin: you're all set on https://MY-JENKINS-URL/"}],"mrkdwn_in":["pretext","text","fields"]}],"link_names":"1","unfurl_links":"true","unfurl_media":"true","channel":"complete-wrong-channel","as_user":"true"}

Sep 08, 2020 10:33:21 AM WARNING jenkins.plugins.slack.StandardSlackService postToSlack

Slack post may have failed. Response: null

Sep 08, 2020 10:33:21 AM WARNING jenkins.plugins.slack.StandardSlackService postToSlack

Response Code: 302

I run the "test" message, please note that I've also tried with a complete wrong token and a complete wrong channel, still 302 as response code.

If I check "Custom slack app bot user" on Jenkins I then get

Posting: to MY-CHANNEL on faceit:  {"attachments":[{"fallback":"Slack/Jenkins plugin: you're all set on https://MY-JENKINS-URL/","color":"good","fields":[{"short":false,"value":"Slack/Jenkins plugin: you're all set on https://MY-JENKINS-URL/"}],"mrkdwn_in":["pretext","text","fields"]}],"link_names":"1","unfurl_links":"true","unfurl_media":"true","channel":"MY-CHANNEL","as_user":"true"}

Sep 08, 2020 10:36:01 AM WARNING jenkins.plugins.slack.StandardSlackService postToSlack

Slack post may have failed.  Invalid JSON response: 

Sep 08, 2020 10:36:01 AM WARNING jenkins.plugins.slack.StandardSlackService postToSlack

Slack post may have failed. Response: 

Sep 08, 2020 10:36:01 AM WARNING jenkins.plugins.slack.StandardSlackService postToSlack

Response Code: 302

Still 302 but with the "Invalid JSON response"

timja commented 4 years ago

Is there a url logged on where the request is going? you can *** out the token.

emas80 commented 4 years ago

No urls, as you could see some logs are using the FINE level. When I've created the logger as instructed I set to log "ALL".

timja commented 4 years ago

Try add org.apache.http to the loggers

https://hc.apache.org/httpcomponents-client-4.5.x/logging.html

emas80 commented 4 years ago

Ok, we've got something:

Sep 08, 2020 2:28:21 PM FINE jenkins.plugins.slack.StandardSlackService

Posting: to #MY-CHANNEL on faceit:  {"attachments":[{"fallback":"Slack/Jenkins plugin: you're all set on https://MY-JENKINS/","color":"good","fields":[{"short":false,"value":"Slack/Jenkins plugin: you're all set on https://MY-JENKINS/"}],"mrkdwn_in":["pretext","text","fields"]}],"link_names":"1","unfurl_links":"true","unfurl_media":"true","channel":"#MY-CHANNEL","as_user":"true"}

Sep 08, 2020 2:28:21 PM FINE org.apache.http.client.protocol.RequestAddCookies process

CookieSpec selected: default

Sep 08, 2020 2:28:21 PM FINE org.apache.http.client.protocol.RequestAuthCache process

Auth cache not set in the context

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.PoolingHttpClientConnectionManager requestConnection

Connection request: [route: {s}->https://hooks.slack.com:443][total kept alive: 0; route allocated: 0 of 5; total allocated: 0 of 10]

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.PoolingHttpClientConnectionManager leaseConnection

Connection leased: [id: 15][route: {s}->https://hooks.slack.com:443][total kept alive: 0; route allocated: 1 of 5; total allocated: 1 of 10]

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.execchain.MainClientExec execute

Opening connection {s}->https://hooks.slack.com:443

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.DefaultHttpClientConnectionOperator connect

Connecting to hooks.slack.com/18.214.242.166:443

Sep 08, 2020 2:28:21 PM FINE org.apache.http.conn.ssl.SSLConnectionSocketFactory connectSocket

Connecting socket to hooks.slack.com/18.214.242.166:443 with timeout 60000

Sep 08, 2020 2:28:21 PM FINE org.apache.http.conn.ssl.SSLConnectionSocketFactory createLayeredSocket

Enabled protocols: [TLSv1, TLSv1.1, TLSv1.2]

Sep 08, 2020 2:28:21 PM FINE org.apache.http.conn.ssl.SSLConnectionSocketFactory createLayeredSocket

Enabled cipher suites:[TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384, TLS_RSA_WITH_AES_256_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384, TLS_DHE_RSA_WITH_AES_256_CBC_SHA256, TLS_DHE_DSS_WITH_AES_256_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_DSS_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_DSS_WITH_AES_128_GCM_SHA256, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]

Sep 08, 2020 2:28:21 PM FINE org.apache.http.conn.ssl.SSLConnectionSocketFactory createLayeredSocket

Starting handshake

Sep 08, 2020 2:28:21 PM FINE org.apache.http.conn.ssl.SSLConnectionSocketFactory verifyHostname

Secure session established

Sep 08, 2020 2:28:21 PM FINE org.apache.http.conn.ssl.SSLConnectionSocketFactory verifyHostname

 negotiated protocol: TLSv1.2

Sep 08, 2020 2:28:21 PM FINE org.apache.http.conn.ssl.SSLConnectionSocketFactory verifyHostname

 negotiated cipher suite: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256

Sep 08, 2020 2:28:21 PM FINE org.apache.http.conn.ssl.SSLConnectionSocketFactory verifyHostname

 peer principal: CN=slack.com, O="Slack Technologies, Inc.", L=San Francisco, ST=CA, C=US

Sep 08, 2020 2:28:21 PM FINE org.apache.http.conn.ssl.SSLConnectionSocketFactory verifyHostname

 peer alternative names: [slack.com, *.slack.com]

Sep 08, 2020 2:28:21 PM FINE org.apache.http.conn.ssl.SSLConnectionSocketFactory verifyHostname

 issuer principal: CN=DigiCert SHA2 Secure Server CA, O=DigiCert Inc, C=US

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.DefaultHttpClientConnectionOperator connect

Connection established 10.4.12.12:54704<->18.214.242.166:443

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection setSocketTimeout

http-outgoing-15: set socket timeout to 60000

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.execchain.MainClientExec execute

Executing request POST /services/XXXXXX HTTP/1.1

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.execchain.MainClientExec execute

Target auth state: UNCHALLENGED

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.execchain.MainClientExec execute

Proxy auth state: UNCHALLENGED

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection onRequestSubmitted

http-outgoing-15 >> POST /services/XXX HTTP/1.1

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection onRequestSubmitted

http-outgoing-15 >> Content-Type: application/json; charset=utf-8

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection onRequestSubmitted

http-outgoing-15 >> Content-Length: 386

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection onRequestSubmitted

http-outgoing-15 >> Host: hooks.slack.com

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection onRequestSubmitted

http-outgoing-15 >> Connection: Keep-Alive

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection onRequestSubmitted

http-outgoing-15 >> User-Agent: Apache-HttpClient/4.5.10 (Java/1.8.0_262)

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection onRequestSubmitted

http-outgoing-15 >> Accept-Encoding: gzip,deflate

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 >> "POST /services/XXX HTTP/1.1[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 >> "Content-Type: application/json; charset=utf-8[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 >> "Content-Length: 386[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 >> "Host: hooks.slack.com[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 >> "Connection: Keep-Alive[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 >> "User-Agent: Apache-HttpClient/4.5.10 (Java/1.8.0_262)[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 >> "Accept-Encoding: gzip,deflate[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 >> "[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 >> "{"attachments":[{"fallback":"Slack/Jenkins plugin: you're all set on https://MY-JENKINS/","color":"good","fields":[{"short":false,"value":"Slack/Jenkins plugin: you're all set on https://MY-JENKINS/"}],"mrkdwn_in":["pretext","text","fields"]}],"link_names":"1","unfurl_links":"true","unfurl_media":"true","channel":"#MY-CHANNEL","as_user":"true"}"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 << "HTTP/1.1 302 Found[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 << "date: Tue, 08 Sep 2020 14:28:21 GMT[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 << "server: Apache[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 << "strict-transport-security: max-age=31536000; includeSubDomains; preload[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 << "referrer-policy: no-referrer[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 << "vary: Accept-Encoding[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 << "x-slack-backend: r[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 << "x-frame-options: SAMEORIGIN, SAMEORIGIN[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 << "location: https://api.slack.com/[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 << "content-length: 0[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 << "content-type: text/html[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 << "x-via: haproxy-www-vtio,haproxy-edge-iad-e32l[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.Wire wire

http-outgoing-15 << "[\r][\n]"

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection onResponseReceived

http-outgoing-15 << HTTP/1.1 302 Found

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection onResponseReceived

http-outgoing-15 << date: Tue, 08 Sep 2020 14:28:21 GMT

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection onResponseReceived

http-outgoing-15 << server: Apache

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection onResponseReceived

http-outgoing-15 << strict-transport-security: max-age=31536000; includeSubDomains; preload

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection onResponseReceived

http-outgoing-15 << referrer-policy: no-referrer

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection onResponseReceived

http-outgoing-15 << vary: Accept-Encoding

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection onResponseReceived

http-outgoing-15 << x-slack-backend: r

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection onResponseReceived

http-outgoing-15 << x-frame-options: SAMEORIGIN, SAMEORIGIN

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection onResponseReceived

http-outgoing-15 << location: https://api.slack.com/

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection onResponseReceived

http-outgoing-15 << content-length: 0

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection onResponseReceived

http-outgoing-15 << content-type: text/html

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection onResponseReceived

http-outgoing-15 << x-via: haproxy-www-vtio,haproxy-edge-iad-e32l

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.execchain.MainClientExec execute

Connection can be kept alive indefinitely

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.PoolingHttpClientConnectionManager releaseConnection

Connection [id: 15][route: {s}->https://hooks.slack.com:443] can be kept alive indefinitely

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection setSocketTimeout

http-outgoing-15: set socket timeout to 0

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.PoolingHttpClientConnectionManager releaseConnection

Connection released: [id: 15][route: {s}->https://hooks.slack.com:443][total kept alive: 1; route allocated: 1 of 5; total allocated: 1 of 10]

Sep 08, 2020 2:28:21 PM WARNING jenkins.plugins.slack.StandardSlackService postToSlack

Slack post may have failed. Response: null

Sep 08, 2020 2:28:21 PM WARNING jenkins.plugins.slack.StandardSlackService postToSlack

Response Code: 302

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.execchain.ConnectionHolder cancel

Cancelling request execution

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.PoolingHttpClientConnectionManager shutdown

Connection manager is shutting down

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.LoggingManagedHttpClientConnection close

http-outgoing-15: Close connection

Sep 08, 2020 2:28:21 PM FINE org.apache.http.impl.conn.PoolingHttpClientConnectionManager shutdown

Connection manager shut down

There is a redirection from hooks.slack.com to api.slack.com which is probably not followed

timja commented 4 years ago

can you please screenshot your configuration?

emas80 commented 4 years ago

Ok, I have found one issue, while I was checking the configuration.

I had this thought: let's try one more time since the beginning - New App, new token starting with "xoxb-", BUT this time I will click "Apply" before clicking "Test Connection".

And I got "Success".

So, if the integration is done by following the documentation at https://github.com/jenkinsci/slack-plugin#creating-your-app, AKA the New Way, everything works properly. The problem was that, even if I was changing for example the token, or ticking the box "Custom slack app bot user", when clicking "Test Connection" it was still taking the old values. I think this should need to be addressed as it's confusing.

Now, this still does not explain why my former integration, configured using the legacy Jenkins CI application (token, empty override url, no tick on "Custom slack app bot user"), stopped working suddenly the last week. I still suspect that something Slack side has changed (I keep thinking at the redirect...) and this might not be handled very well in the plugin.