Conncection closed without response

[DonyorM]

I'm trying to deploy a hello bot onto a heroku dyno. I have the server working and I can actually get a bot's subscription link, but then DevBot gives me the error:

Failed to query: https://safe-reef-88300.herokuapp.com:443/bots/status.
Make sure your service is running and this url is visible

On the heroku logs I see this error:

2017-05-13T13:56:26.088066+00:00 heroku[router]: at=error code=H13 desc="Connection closed without response" method=GET path="/bots/status" host=safe-reef-88300.herokuapp.com request_id=e59b09ec-da74-402f-a6b1-0c368e89f442 fwd="104.199.39.107" dyno=web.1 connect=0ms service=4ms status=503 bytes=0 protocol=https

In order to deploy the application to heroku, I prebuilt the bot on my machine, and then used a Null buildpack so heroku does no building on the server. I am running this in a free web dyno, and I have the https port exposed on 443. What would cause this error?

My echo.yaml is:

server:
  applicationConnectors:
    - type: http
      port: 8049
    - type: https
      port: 443
      keyStorePath: certs/keystore.jks
      keyStorePassword: 123456 
      certAlias: myservercert
      validateCerts: false
      validatePeers: false

  adminConnectors:
    - type: http
      port: 8051
#  requestLog:
#    appenders: []

auth: <bot token>  # obtained from DevBot when running: show bot <name>
name: testbridge
accent: 2
cryptoDir: certs

[dkovacevic]

when I run:
curl -ikv https://safe-reef-88300.herokuapp.com:443/bots/status

I am getting:

*   Trying 54.225.154.132...
* Connected to safe-reef-88300.herokuapp.com (54.225.154.132) port 443 (#0)
* TLS 1.2 connection using TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
* Server certificate: *.herokuapp.com
* Server certificate: DigiCert SHA2 High Assurance Server CA
* Server certificate: DigiCert High Assurance EV Root CA
> GET /bots/status HTTP/1.1
> Host: safe-reef-88300.herokuapp.com
> User-Agent: curl/7.43.0
> Accept: */*
>
< HTTP/1.1 503 Service Unavailable
HTTP/1.1 503 Service Unavailable

Do you still have your echo bot service running there?
Do you have keystore.jsk file in ./certs/ dir?

Can you paste here your logs (current.log) or console output?

[DonyorM]

Service is still running. It shutdowns with lack of inactivity, but starts up as soon as a query comes.

I can see your request in the logs, and it has the same error as DevBot. I also tried the curl request a couple of times, with the same result. The keystore.jks (I'm assuming it needs .jks and not .jsk) is there and works properly, I can view it with keytool --list --keystore keystore.jks.

I do have the unlimited power policy jar files in ${JAVA_HOME}/jre/lib/security

[dkovacevic]

Thanks. What is the output when you start the service?
You should see something like this:

INFO  [2017-05-13 20:59:02,277] org.eclipse.jetty.util.log: Logging initialized @4073ms
INFO  [2017-05-13 20:59:02,400] io.dropwizard.server.DefaultServerFactory: Registering jersey handler with root path prefix: /
INFO  [2017-05-13 20:59:02,401] io.dropwizard.server.DefaultServerFactory: Registering admin handler with root path prefix: /
INFO  [2017-05-13 20:59:02,402] io.dropwizard.assets.AssetsBundle: Registering AssetBundle with name: assets for path /diagnosis/*
INFO  [2017-05-13 20:59:02,447] io.dropwizard.assets.AssetsBundle: Registering AssetBundle with name: assets for path /assets/*
WARN  [2017-05-13 20:59:02,448] io.dropwizard.jetty.setup.ServletEnvironment: Overriding the existing servlet registered with the name: assets
INFO  [2017-05-13 20:59:02,471] io.dropwizard.server.DefaultServerFactory: Registering jersey handler with root path prefix: /
INFO  [2017-05-13 20:59:02,472] io.dropwizard.server.DefaultServerFactory: Registering admin handler with root path prefix: /
INFO  [2017-05-13 20:59:02,473] io.dropwizard.server.ServerFactory: Starting EchoService
INFO  [2017-05-13 20:59:02,863] org.eclipse.jetty.setuid.SetUIDListener: Opened application@24f360b2{HTTP/1.1,[http/1.1]}{0.0.0.0:8049}
INFO  [2017-05-13 20:59:02,865] org.eclipse.jetty.setuid.SetUIDListener: Opened application@60cf80e7{SSL,[ssl, http/1.1]}{0.0.0.0:443}
INFO  [2017-05-13 20:59:02,868] org.eclipse.jetty.setuid.SetUIDListener: Opened admin@302fec27{HTTP/1.1,[http/1.1]}{0.0.0.0:8051}
INFO  [2017-05-13 20:59:02,870] org.eclipse.jetty.server.Server: jetty-9.3.z-SNAPSHOT
INFO  [2017-05-13 20:59:03,120] org.eclipse.jetty.util.ssl.SslContextFactory: x509=X509@2a492f2a(myservercert,h=[company.com],w=[]) for SslContextFactory@3277e499(file:///opt/echo/keystore.jks,null)
INFO  [2017-05-13 20:59:03,619] io.dropwizard.jetty.HttpsConnectorFactory: Supported protocols: [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2]
INFO  [2017-05-13 20:59:03,625] io.dropwizard.jetty.HttpsConnectorFactory: Supported 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_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV, TLS_DH_anon_WITH_AES_256_GCM_SHA384, TLS_DH_anon_WITH_AES_128_GCM_SHA256, TLS_DH_anon_WITH_AES_256_CBC_SHA256, TLS_ECDH_anon_WITH_AES_256_CBC_SHA, TLS_DH_anon_WITH_AES_256_CBC_SHA, TLS_DH_anon_WITH_AES_128_CBC_SHA256, TLS_ECDH_anon_WITH_AES_128_CBC_SHA, TLS_DH_anon_WITH_AES_128_CBC_SHA, TLS_ECDH_anon_WITH_3DES_EDE_CBC_SHA, SSL_DH_anon_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_DES_CBC_SHA, SSL_DHE_RSA_WITH_DES_CBC_SHA, SSL_DHE_DSS_WITH_DES_CBC_SHA, SSL_DH_anon_WITH_DES_CBC_SHA, SSL_RSA_EXPORT_WITH_DES40_CBC_SHA, SSL_DHE_RSA_EXPORT_WITH_DES40_CBC_SHA, SSL_DHE_DSS_EXPORT_WITH_DES40_CBC_SHA, SSL_DH_anon_EXPORT_WITH_DES40_CBC_SHA, TLS_RSA_WITH_NULL_SHA256, TLS_ECDHE_ECDSA_WITH_NULL_SHA, TLS_ECDHE_RSA_WITH_NULL_SHA, SSL_RSA_WITH_NULL_SHA, TLS_ECDH_ECDSA_WITH_NULL_SHA, TLS_ECDH_RSA_WITH_NULL_SHA, TLS_ECDH_anon_WITH_NULL_SHA, SSL_RSA_WITH_NULL_MD5, TLS_KRB5_WITH_3DES_EDE_CBC_SHA, TLS_KRB5_WITH_3DES_EDE_CBC_MD5, TLS_KRB5_WITH_DES_CBC_SHA, TLS_KRB5_WITH_DES_CBC_MD5, TLS_KRB5_EXPORT_WITH_DES_CBC_40_SHA, TLS_KRB5_EXPORT_WITH_DES_CBC_40_MD5]
INFO  [2017-05-13 20:59:04,626] io.dropwizard.jersey.DropwizardResourceConfig: The following paths were found for the configured resources:

    POST    /bots (com.wire.bots.sdk.server.resources.BotsResource)
    GET     /bots/status (com.wire.bots.sdk.server.resources.StatusResource)
    POST    /bots/{bot}/messages (com.wire.bots.sdk.server.resources.MessageResource)
    POST    /provider/diagnosis (com.wire.bots.sdk.server.resources.ProviderResource)
    POST    /provider/login (com.wire.bots.sdk.server.resources.ProviderResource)
    GET     /provider/services (com.wire.bots.sdk.server.resources.ProviderResource)

INFO  [2017-05-13 20:59:04,628] org.eclipse.jetty.server.handler.ContextHandler: Started i.d.j.MutableServletContextHandler@43a51d00{/,null,AVAILABLE}
INFO  [2017-05-13 20:59:04,643] io.dropwizard.setup.AdminEnvironment: tasks = 

    POST    /tasks/prekeys (com.wire.bots.sdk.server.tasks.AvailablePrekeysTask)
    POST    /tasks/log-level (io.dropwizard.servlets.tasks.LogConfigurationTask)
    POST    /tasks/gc (io.dropwizard.servlets.tasks.GarbageCollectionTask)
    POST    /tasks/hello_task (com.wire.bots.echo.EchoService$1)
    POST    /tasks/conversation (com.wire.bots.sdk.server.tasks.ConversationTask)
    POST    /tasks/broadcast (com.wire.bots.sdk.server.tasks.BroadcastAllTask)

INFO  [2017-05-13 20:59:04,647] org.eclipse.jetty.server.handler.ContextHandler: Started i.d.j.MutableServletContextHandler@63bde6c2{/,null,AVAILABLE}
INFO  [2017-05-13 20:59:04,658] org.eclipse.jetty.server.AbstractConnector: Started application@24f360b2{HTTP/1.1,[http/1.1]}{0.0.0.0:8049}
INFO  [2017-05-13 20:59:04,677] org.eclipse.jetty.server.AbstractConnector: Started application@60cf80e7{SSL,[ssl, http/1.1]}{0.0.0.0:443}
INFO  [2017-05-13 20:59:04,678] org.eclipse.jetty.server.AbstractConnector: Started admin@302fec27{HTTP/1.1,[http/1.1]}{0.0.0.0:8051}
INFO  [2017-05-13 20:59:04,678] org.eclipse.jetty.server.Server: Started @6476ms

[DonyorM]

That's pretty much what I'm getting. This is what I got exactly:

 Starting process with command `java $JAVA_OPTS -Ddw.server.applicationConnectors[1].port=9677 -jar target/echo.jar server conf/echo.yaml`
2017-05-13T21:06:25.733245+00:00 app[web.1]: Setting JAVA_TOOL_OPTIONS defaults based on dyno size. Custom settings will override them.
2017-05-13T21:06:25.743523+00:00 app[web.1]: Picked up JAVA_TOOL_OPTIONS: -Xmx350m -Xss512k -Dfile.encoding=UTF-8
2017-05-13T21:06:28.254832+00:00 app[web.1]: INFO  [2017-05-13 21:06:28,249] org.eclipse.jetty.util.log: Logging initialized @2509ms
2017-05-13T21:06:28.365733+00:00 app[web.1]: INFO  [2017-05-13 21:06:28,365] io.dropwizard.server.DefaultServerFactory: Registering jersey handler with root path prefix: /
2017-05-13T21:06:28.365778+00:00 app[web.1]: INFO  [2017-05-13 21:06:28,365] io.dropwizard.server.DefaultServerFactory: Registering admin handler with root path prefix: /
2017-05-13T21:06:28.365926+00:00 app[web.1]: INFO  [2017-05-13 21:06:28,365] io.dropwizard.assets.AssetsBundle: Registering AssetBundle with name: assets for path /diagnosis/*
2017-05-13T21:06:28.405334+00:00 app[web.1]: INFO  [2017-05-13 21:06:28,405] io.dropwizard.assets.AssetsBundle: Registering AssetBundle with name: assets for path /assets/*
2017-05-13T21:06:28.405361+00:00 app[web.1]: WARN  [2017-05-13 21:06:28,405] io.dropwizard.jetty.setup.ServletEnvironment: Overriding the existing servlet registered with the name: assets
2017-05-13T21:06:28.423401+00:00 app[web.1]: INFO  [2017-05-13 21:06:28,423] io.dropwizard.server.DefaultServerFactory: Registering jersey handler with root path prefix: /
2017-05-13T21:06:28.423564+00:00 app[web.1]: INFO  [2017-05-13 21:06:28,423] io.dropwizard.server.DefaultServerFactory: Registering admin handler with root path prefix: /
2017-05-13T21:06:28.426217+00:00 app[web.1]: INFO  [2017-05-13 21:06:28,425] io.dropwizard.server.ServerFactory: Starting EchoService
2017-05-13T21:06:28.696954+00:00 app[web.1]: INFO  [2017-05-13 21:06:28,696] org.eclipse.jetty.setuid.SetUIDListener: Opened application@5ae76500{HTTP/1.1,[http/1.1]}{0.0.0.0:8049}
2017-05-13T21:06:28.698521+00:00 app[web.1]: INFO  [2017-05-13 21:06:28,698] org.eclipse.jetty.setuid.SetUIDListener: Opened application@6063d80a{SSL,[ssl, http/1.1]}{0.0.0.0:9677}
2017-05-13T21:06:28.698948+00:00 app[web.1]: INFO  [2017-05-13 21:06:28,698] org.eclipse.jetty.setuid.SetUIDListener: Opened admin@1133ec6e{HTTP/1.1,[http/1.1]}{0.0.0.0:8051}
2017-05-13T21:06:28.701626+00:00 app[web.1]: INFO  [2017-05-13 21:06:28,701] org.eclipse.jetty.server.Server: jetty-9.3.z-SNAPSHOT
2017-05-13T21:06:28.784118+00:00 app[web.1]: INFO  [2017-05-13 21:06:28,783] org.eclipse.jetty.util.ssl.SslContextFactory: x509=X509@63f34b70(myservercert,h=[company.com],w=[]) for SslContextFactory@641856(file:///app/certs/keystore.jks,null)
2017-05-13T21:06:28.787248+00:00 heroku[web.1]: State changed from starting to up
2017-05-13T21:06:28.958197+00:00 app[web.1]: INFO  [2017-05-13 21:06:28,957] io.dropwizard.jetty.HttpsConnectorFactory: Supported protocols: [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2]
2017-05-13T21:06:28.959227+00:00 app[web.1]: INFO  [2017-05-13 21:06:28,959] io.dropwizard.jetty.HttpsConnectorFactory: Supported 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_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV, TLS_DH_anon_WITH_AES_256_GCM_SHA384, TLS_DH_anon_WITH_AES_128_GCM_SHA256, TLS_DH_anon_WITH_AES_256_CBC_SHA256, TLS_ECDH_anon_WITH_AES_256_CBC_SHA, TLS_DH_anon_WITH_AES_256_CBC_SHA, TLS_DH_anon_WITH_AES_128_CBC_SHA256, TLS_ECDH_anon_WITH_AES_128_CBC_SHA, TLS_DH_anon_WITH_AES_128_CBC_SHA, TLS_ECDH_anon_WITH_3DES_EDE_CBC_SHA, SSL_DH_anon_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_DES_CBC_SHA, SSL_DHE_RSA_WITH_DES_CBC_SHA, SSL_DHE_DSS_WITH_DES_CBC_SHA, SSL_DH_anon_WITH_DES_CBC_SHA, SSL_RSA_EXPORT_WITH_DES40_CBC_SHA, SSL_DHE_RSA_EXPORT_WITH_DES40_CBC_SHA, SSL_DHE_DSS_EXPORT_WITH_DES40_CBC_SHA, SSL_DH_anon_EXPORT_WITH_DES40_CBC_SHA, TLS_RSA_WITH_NULL_SHA256, TLS_ECDHE_ECDSA_WITH_NULL_SHA, TLS_ECDHE_RSA_WITH_NULL_SHA, SSL_RSA_WITH_NULL_SHA, TLS_ECDH_ECDSA_WITH_NULL_SHA, TLS_ECDH_RSA_WITH_NULL_SHA, TLS_ECDH_anon_WITH_NULL_SHA, SSL_RSA_WITH_NULL_MD5, TLS_KRB5_WITH_3DES_EDE_CBC_SHA, TLS_KRB5_WITH_3DES_EDE_CBC_MD5, TLS_KRB5_WITH_DES_CBC_SHA, TLS_KRB5_WITH_DES_CBC_MD5, TLS_KRB5_EXPORT_WITH_DES_CBC_40_SHA, TLS_KRB5_EXPORT_WITH_DES_CBC_40_MD5]
2017-05-13T21:06:29.982064+00:00 app[web.1]: INFO  [2017-05-13 21:06:29,981] io.dropwizard.jersey.DropwizardResourceConfig: The following paths were found for the configured resources:
2017-05-13T21:06:29.982077+00:00 app[web.1]: 
2017-05-13T21:06:29.982078+00:00 app[web.1]:     POST    /bots (com.wire.bots.sdk.server.resources.BotsResource)
2017-05-13T21:06:29.982079+00:00 app[web.1]:     GET     /bots/status (com.wire.bots.sdk.server.resources.StatusResource)
2017-05-13T21:06:29.982080+00:00 app[web.1]:     POST    /bots/{bot}/messages (com.wire.bots.sdk.server.resources.MessageResource)
2017-05-13T21:06:29.982081+00:00 app[web.1]:     POST    /provider/diagnosis (com.wire.bots.sdk.server.resources.ProviderResource)
2017-05-13T21:06:29.982081+00:00 app[web.1]:     POST    /provider/login (com.wire.bots.sdk.server.resources.ProviderResource)
2017-05-13T21:06:29.982082+00:00 app[web.1]:     GET     /provider/services (com.wire.bots.sdk.server.resources.ProviderResource)
2017-05-13T21:06:29.982083+00:00 app[web.1]: 
2017-05-13T21:06:29.984051+00:00 app[web.1]: INFO  [2017-05-13 21:06:29,983] org.eclipse.jetty.server.handler.ContextHandler: Started i.d.j.MutableServletContextHandler@22590e3e{/,null,AVAILABLE}
2017-05-13T21:06:29.993133+00:00 app[web.1]: INFO  [2017-05-13 21:06:29,992] io.dropwizard.setup.AdminEnvironment: tasks = 
2017-05-13T21:06:29.993135+00:00 app[web.1]: 
2017-05-13T21:06:29.993137+00:00 app[web.1]:     POST    /tasks/prekeys (com.wire.bots.sdk.server.tasks.AvailablePrekeysTask)
2017-05-13T21:06:29.993137+00:00 app[web.1]:     POST    /tasks/log-level (io.dropwizard.servlets.tasks.LogConfigurationTask)
2017-05-13T21:06:29.993138+00:00 app[web.1]:     POST    /tasks/gc (io.dropwizard.servlets.tasks.GarbageCollectionTask)
2017-05-13T21:06:29.993139+00:00 app[web.1]:     POST    /tasks/hello_task (com.wire.bots.echo.EchoService$1)
2017-05-13T21:06:29.993139+00:00 app[web.1]:     POST    /tasks/conversation (com.wire.bots.sdk.server.tasks.ConversationTask)
2017-05-13T21:06:29.993140+00:00 app[web.1]:     POST    /tasks/broadcast (com.wire.bots.sdk.server.tasks.BroadcastAllTask)
2017-05-13T21:06:29.993141+00:00 app[web.1]: 
2017-05-13T21:06:29.999976+00:00 app[web.1]: INFO  [2017-05-13 21:06:29,999] org.eclipse.jetty.server.handler.ContextHandler: Started i.d.j.MutableServletContextHandler@173f73e7{/,null,AVAILABLE}
2017-05-13T21:06:30.009664+00:00 app[web.1]: INFO  [2017-05-13 21:06:30,009] org.eclipse.jetty.server.AbstractConnector: Started application@5ae76500{HTTP/1.1,[http/1.1]}{0.0.0.0:8049}
2017-05-13T21:06:30.014420+00:00 app[web.1]: INFO  [2017-05-13 21:06:30,013] org.eclipse.jetty.server.AbstractConnector: Started application@6063d80a{SSL,[ssl, http/1.1]}{0.0.0.0:9677}
2017-05-13T21:06:30.018532+00:00 app[web.1]: INFO  [2017-05-13 21:06:30,018] org.eclipse.jetty.server.AbstractConnector: Started admin@1133ec6e{HTTP/1.1,[http/1.1]}{0.0.0.0:8051}
2017-05-13T21:06:30.018797+00:00 app[web.1]: INFO  [2017-05-13 21:06:30,018] org.eclipse.jetty.server.Server: Started @4280ms

The difference appears to be mostly Heroku's boilerplate that they put before log lines.

Sorry that this is so complicated, I'm probably missing something really simple.

[dkovacevic]

In your logs:

Starting process with command java $JAVA_OPTS -Ddw.server.applicationConnectors[1].port=9677 -jar target/echo.jar server conf/echo.yaml

This means you are overriding your https port 443 specified in yaml with 9677 which is probably not opened.

2017-05-13T21:06:30.014420+00:00 app[web.1]: INFO  [2017-05-13 21:06:30,013] org.eclipse.jetty.server.AbstractConnector: Started application@6063d80a{SSL,[ssl, http/1.1]}{0.0.0.0:9677}

Either open 9677 and update your URL with DevBot or change java command.

[DonyorM]

The way Heroku works you have to bind to a specific port they give (and changes with each instance) which they somehow reroute to port 443 for your specific instance (reference: https://stackoverflow.com/questions/9164915/node-js-eacces-error-when-listening-on-most-ports#comment11532456_9166332)

Anyway, I get this error when I run curl -ikv https://safe-reef-88300.herokuapp.com:9677/bots/status

* Hostname was NOT found in DNS cache
*   Trying 54.197.233.136...
* connect to 54.197.233.136 port 9677 failed: Connection refused
* Failed to connect to safe-reef-88300.herokuapp.com port 9677: Connection refused
* Closing connection 0
curl: (7) Failed to connect to safe-reef-88300.herokuapp.com port 9677: Connection refused

It appears to only be listening on 443. Sorry for that little confusion with Heroku.

[dkovacevic]

I see. OK so it's clear that Heroku is not routing traffic from 443 to 9677 correctly. I will try to investigate bot deployments to Heroku more on Monday. Meanwhile if you find a cause for this please elaborate it here so other people dont have to go through this. Thanks!

[DonyorM]

I will contact heroku support and see if they can help me in any way. I plan to release my edits to github once I get it working, so hopefully I'll have a template out soon.

[dkovacevic]

One more thing. Can you verify that you provided Dev Bot with the correct string from pubkey.pem?
You can always update your pubkey by running: update bot <bot_name> and then pubkey

[DonyorM]

Same error even after I updated the pubkey.

I tried running a fresh copy of this git repository on my own machine (all I did was make and change the echo.yaml so it had access to the keystore and an open port) and tried curl -ikv localhost:4434/bots/status
With this result:

* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 4434 (#0)
> GET /bots/status HTTP/1.1
> User-Agent: curl/7.35.0
> Host: localhost:4434
> Accept: */*
> 
* Empty reply from server
* Connection #0 to host localhost left intact
curl: (52) Empty reply from server

It seems I'm getting the same error even without Heroku's weirdness.

[dkovacevic]

I think this is fine:
If you try adding https like: curl -ikv https://localhost:4434/bots/status

You should see something like:

*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 4434 (#0)
* TLS 1.2 connection using TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384
* Server certificate: company.com
> GET /bots/status HTTP/1.1
> Host: localhost:4434
> User-Agent: curl/7.43.0
> Accept: */*
> 
< HTTP/1.1 200 OK
HTTP/1.1 200 OK
< Date: Mon, 15 May 2017 21:08:23 GMT
Date: Mon, 15 May 2017 21:08:23 GMT
< Content-Type: text/plain
Content-Type: text/plain
< Vary: Accept-Encoding
Vary: Accept-Encoding
< Content-Length: 8

[DonyorM]

Ah I right. That worked (though my Content-Length is 0, probably not an issue). Sorry for the confusion. I have a ticket in with Heroku, we'll see what they say.

[DonyorM]

Ok got a response back from Heroku. Supposedly, everything is forwarded as if 443 is bound, but the rep did say this, which might be our issue:

All HTTPS request will be sent to your apps port it is listening on. One thing to note that is the SSL connection is terminated before the request reaches your app and our routers send the request to your app via HTTP. Your app will only need to handle HTTP traffic.

Does the bot have an issue if it's receiving HTTP traffic?

[mythsunwind]

Yes, that might be the problem. If you have a config like this:

server:
  applicationConnectors:
    - type: http
      port: 8049
    - type: https
      port: 443
...

the bot expects https on port 443.

What you can do is try the following:

server:
  applicationConnectors:
    - type: http
      port: 443
...

You probably can remove the whole config underneath type: https. If not, just change it into a different port that is not reachable from outside.