Better logging for IOException when sending notification.

[dannyNK]

I cannot seem to use the plugin, I keep getting a "Failed to send notification!" when hitting the test button. I assume I've set something up wrong, but there isn't much to setup :/

I tried using both a token and a webhook. TeamCity version: 9.1 (build 36973)

Stacktrace from teamcity-server.log:

java.io.IOException: Attempted read from closed stream.
    at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:167)
    at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:137)
    at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:283)
    at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:325)
    at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:177)
    at java.io.InputStreamReader.read(InputStreamReader.java:184)
    at java.io.Reader.read(Reader.java:140)
    at org.apache.http.util.EntityUtils.toString(EntityUtils.java:244)
    at org.apache.http.util.EntityUtils.toString(EntityUtils.java:288)
    at slacknotifications.SlackNotificationImpl.postViaApi(SlackNotificationImpl.java:198)
    at slacknotifications.SlackNotificationImpl.post(SlackNotificationImpl.java:152)
    at slacknotifications.teamcity.extension.SlackNotifierSettingsController.handleTestNotification(SlackNotifierSettingsController.java:119)
    at slacknotifications.teamcity.extension.SlackNotifierSettingsController.doHandle(SlackNotifierSettingsController.java:74)
    at jetbrains.buildServer.controllers.BaseController.handleRequestInternal(BaseController.java:78)
    at org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:154)
    at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:50)
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:938)
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:870)
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:961)
    at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:852)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:620)
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:837)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
    at jetbrains.buildServer.maintenance.TeamCityDispatcherServlet.service(TeamCityDispatcherServlet.java:22)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at jetbrains.buildServer.web.DependencyParametersCalculationContextFilter.doFilter(DependencyParametersCalculationContextFilter.java:1)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at jetbrains.buildServer.web.DisableSessionIdFromUrlFilter.doFilter(DisableSessionIdFromUrlFilter.java:7)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at jetbrains.buildServer.diagnostic.web.DiagnosticFilter.doFilter(DiagnosticFilter.java:37)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at jetbrains.buildServer.web.ResponseFragmentFilter.doFilter(ResponseFragmentFilter.java:25)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:421)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1074)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1739)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1698)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)

[PeteGoo]

Eeeek. If you swap out for the previous release, does it still error?

[dannyNK]

Downgraded to 1.4.2 (I think, I changed the zip, and restarted and the log is showing 1.4.2 in its startup splurge), still seeing the same error.

[dannyNK]

I deleted the slack-config.xml, filled everything out again on 1.4.2, revoked and created a new token and it worked! No idea what happened there, but I'm not seeing the issue now.

[kylegrymonprez]

I'm seeing this issue in 1.4.4 - will try deleting the slack-config.xml and trying again. Currently the test notification works, but not the actual sending of the notification from a rule.

[2016-03-03 10:18:20,251] WARN - jetbrains.buildServer.SERVER - Attempted read from closed stream. java.io.IOException: Attempted read from closed stream. at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:167) at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:137) at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284) at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326) at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178) at java.io.InputStreamReader.read(InputStreamReader.java:184) at java.io.Reader.read(Reader.java:140) at org.apache.http.util.EntityUtils.toString(EntityUtils.java:244) at org.apache.http.util.EntityUtils.toString(EntityUtils.java:288) at slacknotifications.SlackNotificationImpl.postViaWebHook(SlackNotificationImpl.java:259) at slacknotifications.SlackNotificationImpl.post(SlackNotificationImpl.java:155) at slacknotifications.teamcity.SlackNotificator.doNotification(SlackNotificator.java:242) at slacknotifications.teamcity.SlackNotificator.notifyBuildStarted(SlackNotificator.java:72) at jetbrains.buildServer.notification.impl.UserRulesAwareNotificationListener$NotificatorEventAdapter.buildStarted(UserRulesAwareNotificationListener.java:140) at jetbrains.buildServer.notification.impl.UserRulesAwareNotificationListener.buildStarted(UserRulesAwareNotificationListener.java:59) at jetbrains.buildServer.notification.NotificationProcessor$1.call(NotificationProcessor.java) at jetbrains.buildServer.notification.NotificationProcessor$18.run(NotificationProcessor.java:4) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745)

[PeteGoo]

THanks. I'm pretty sure there is an HTTP error code hiding in the response somewhere that we aren't surfacing in the logs. Can you try posting manually to this endpoint via Postman or some other method and check if it works?

[kylegrymonprez]

Sure - I'll check out how to do that. FWIW, the test notification works properly, just not a regularly triggered one.

[kylegrymonprez]

Seems like the payload in the log is not a valid JSON:

[2016-03-03 12:10:30,733] INFO - jetbrains.buildServer.SERVER - SlackNotificationListener :: Body message will be payload=%7B%22channel%22%3A%22%40%40kyle.grymonprez%22%2C%22username%22%3A%22sc-teamcity%22%2C%22text%22%3A%22%5Cu003chttp%3A%2F%2Fsc-teamcity.glu.com%2FviewLog.html%3FbuildTypeId%5Cu003dResearch_ANotificationManagerGithub%5Cu0026buildId%5Cu003d63191%7CSucceeded+-+Research+%3A%3A+ANotificationManager+Github+%23121%5Cu003e%22%2C%22icon_url%22%3A%22https%3A%2F%2Fraw.githubusercontent.com%2FPeteGoo%2FtcSlackBuildNotifier%2Fmaster%2Fdocs%2FTeamCity.png%22%2C%22attachments%22%3A%5B%7B%22color%22%3A%22good%22%2C%22fields%22%3A%5B%7B%22title%22%3A%22ANotificationManager+Github%22%2C%22value%22%3A%22Agent%3A+sf-mp-3365%5CnElapsed%3A+29s%22%2C%22isShort%22%3Afalse%7D%5D%2C%22fallback%22%3A%22ANotificationManager+Github%22%7D%5D%7D

[kylegrymonprez]

apoligies - seems that the username I entered in the settings had "@" in it and the plugin added another "@". Could be a feature request to detect it, but removing the second "@" seems to have addressed the issues....

[PeteGoo]

Awesome. Glad to hear you resolved it I'll re-open this bug to detect the correct error status and log better messages.