echo-bot icon indicating copy to clipboard operation
echo-bot copied to clipboard
verified publisher icon wireapp

Conncection closed without response

Open DonyorM opened this issue 8 years ago • 33 comments

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

DonyorM avatar May 13 '17 14:05 DonyorM

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?

dkovacevic avatar May 13 '17 20:05 dkovacevic

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

DonyorM avatar May 13 '17 20:05 DonyorM

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

dkovacevic avatar May 13 '17 21:05 dkovacevic

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.

DonyorM avatar May 13 '17 21:05 DonyorM

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.

dkovacevic avatar May 13 '17 21:05 dkovacevic

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.

DonyorM avatar May 13 '17 21:05 DonyorM

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!

dkovacevic avatar May 13 '17 21:05 dkovacevic

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.

DonyorM avatar May 13 '17 21:05 DonyorM

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

dkovacevic avatar May 15 '17 12:05 dkovacevic

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.

DonyorM avatar May 15 '17 19:05 DonyorM

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

dkovacevic avatar May 15 '17 21:05 dkovacevic

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 avatar May 15 '17 21:05 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?

DonyorM avatar May 16 '17 12:05 DonyorM

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.

mythsunwind avatar May 16 '17 12:05 mythsunwind

Well that seems to be doing better. I had the server bind it's http port to the public port and use that instead. However, Devbot still won't create the invite link.

I get this message in the logs when Devbot tries to contact the server:

2017-05-16T13:16:21.661444+00:00 heroku[router]: at=info method=GET path="/bots/status" host=safe-reef-88300.herokuapp.com request_id=bd3122ff-be46-4c78-b163-639baccd7473 fwd="104.199.39.107" dyno=web.1 connect=0ms service=12ms status=200 bytes=98 protocol=https
2017-05-16T13:16:21.661032+00:00 app[web.1]: 104.199.39.107 - - [16/May/2017:13:16:21 +0000] "GET /bots/status HTTP/1.1" 200 0 "-" "Jersey/2.23.2 (HttpUrlConnection 1.8.0_91)" 8

If I try curl -ikv https://safe-reef-88300.herokuapp.com/bots/status I get:

* Hostname was NOT found in DNS cache
*   Trying 54.243.117.208...
* Connected to safe-reef-88300.herokuapp.com (54.243.117.208) port 443 (#0)
* successfully set certificate verify locations:
*   CAfile: none
  CApath: /etc/ssl/certs
* SSLv3, TLS handshake, Client hello (1):
* SSLv3, TLS handshake, Server hello (2):
* SSLv3, TLS handshake, CERT (11):
* SSLv3, TLS handshake, Server key exchange (12):
* SSLv3, TLS handshake, Server finished (14):
* SSLv3, TLS handshake, Client key exchange (16):
* SSLv3, TLS change cipher, Client hello (1):
* SSLv3, TLS handshake, Finished (20):
* SSLv3, TLS change cipher, Client hello (1):
* SSLv3, TLS handshake, Finished (20):
* SSL connection using ECDHE-RSA-AES128-GCM-SHA256
* Server certificate:
* 	 subject: C=US; ST=California; L=San Francisco; O=Heroku, Inc.; CN=*.herokuapp.com
* 	 start date: 2017-04-19 00:00:00 GMT
* 	 expire date: 2020-06-22 12:00:00 GMT
* 	 issuer: C=US; O=DigiCert Inc; OU=www.digicert.com; CN=DigiCert SHA2 High Assurance Server CA
* 	 SSL certificate verify ok.
> GET /bots/status HTTP/1.1
> User-Agent: curl/7.35.0
> Host: safe-reef-88300.herokuapp.com
> Accept: */*
> 
< HTTP/1.1 200 OK
HTTP/1.1 200 OK
* Server Cowboy is not blacklisted
< Server: Cowboy
Server: Cowboy
< Connection: close
Connection: close
< Date: Tue, 16 May 2017 13:19:17 GMT
Date: Tue, 16 May 2017 13:19:17 GMT
< Vary: Accept-Encoding
Vary: Accept-Encoding
< Via: 1.1 vegur
Via: 1.1 vegur

< 
* SSLv3, TLS alert, Client hello (1):
* Closing connection 0
* SSLv3, TLS alert, Client hello (1):

It seems to just not be sending anything back.

Edit: Would it help for you to have the bot token and name? This is a test bot that I'll delete after I have this working, so I don't mind that information being public.

DonyorM avatar May 16 '17 13:05 DonyorM

What is your base_url for your bot? What is your bot name?

dkovacevic avatar May 16 '17 13:05 dkovacevic

Bot name is testbridge, base url is https://safe-reef-88300.herokuapp.com. I'm probably missing something rather dumb, sorry to cause this much trouble.

DonyorM avatar May 16 '17 13:05 DonyorM

Thanks. I think Wire Backend does not default to 443 for https. Can you change your base url to: https://safe-reef-88300.herokuapp.com:443 This should fix the glitch with the BE

dkovacevic avatar May 16 '17 13:05 dkovacevic

Same issue:

2017-05-16T13:41:05.619462+00:00 heroku[router]: at=info method=GET path="/bots/status" host=safe-reef-88300.herokuapp.com request_id=2c219076-19d5-4a07-bc73-861667950701 fwd="104.199.39.107" dyno=web.1 connect=0ms service=14ms status=200 bytes=98 protocol=https
2017-05-16T13:41:05.623660+00:00 app[web.1]: 104.199.39.107 - - [16/May/2017:13:41:05 +0000] "GET /bots/status HTTP/1.1" 200 0 "-" "Jersey/2.23.2 (HttpUrlConnection 1.8.0_91)" 11

Curl command looks the same too.

DonyorM avatar May 16 '17 13:05 DonyorM

Yes. If I try to add your bot to a conversation (Chrome console): wire.app.repository.bot.add_bot("testbridge")

I get:

code: 502
label: "bad-gateway
"message: "The upstream service returned an invalid response."

Do you see POST /bots requests coming to your bot service?

dkovacevic avatar May 16 '17 13:05 dkovacevic

BTW: Notice that your GET /bots/status HTTP/1.1" 200 0 returned Status=200 OK. This is valid response. It supposed to return 200 with empty body.

dkovacevic avatar May 16 '17 13:05 dkovacevic

Ok. That's good to know. However I see no Post requests. Dev Bot has not yet succeeded in enabling the bot.

When I try to enable it, I get the same message:

2017-05-16T14:04:29.370155+00:00 heroku[router]: at=info method=GET path="/bots/status" host=safe-reef-88300.herokuapp.com request_id=890fdfd3-dc1b-4941-a590-7019a7ed666e fwd="104.199.39.107" dyno=web.1 connect=0ms service=9ms status=200 bytes=98 protocol=https
2017-05-16T14:04:29.370951+00:00 app[web.1]: 104.199.39.107 - - [16/May/2017:14:04:29 +0000] "GET /bots/status HTTP/1.1" 200 0 "-" "Jersey/2.23.2 (HttpUrlConnection 1.8.0_91)" 5

Of course, all Dev Bot says is "Failed to create invite link" and gives me no other information.

DonyorM avatar May 16 '17 13:05 DonyorM

Can you show me the json you get from Dev Bot when you type: show bot <bot name> Please obfuscate the token Thanks!

dkovacevic avatar May 16 '17 14:05 dkovacevic 

{
  "name" : "testbridge",
  "description" : "testing bot",
  "tags" : [ "tutorial" ],
  "id" : "0e51fe20-efdc-44e3-898e-9e2e07d9386f",
  "enabled" : true,
  "auth_tokens" : [ "----------------------" ],
  "assets" : [ ],
  "base_url" : "https://safe-reef-88300.herokuapp.com:443"
}

Huh, apparently it is enabled, though it doesn't seem to be working right.

DonyorM avatar May 16 '17 14:05 DonyorM

Thanks. You bot is enabled, but there seems to be the problem there. Your service is still returning error ( 403 this time) when Wire BE tries to call POST on /bots

curl -ikv -XPOST https://safe-reef-88300.herokuapp.com:443/bots -d'{}' -H"Content-type:application/json" -H"Authorization:token"
*   Trying 107.21.125.200...
* Connected to safe-reef-88300.herokuapp.com (107.21.125.200) 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
> POST /bots HTTP/1.1
> Host: safe-reef-88300.herokuapp.com
> User-Agent: curl/7.43.0
> Accept: */*
> Content-type:application/json
> Authorization:token
> Content-Length: 2
>
* upload completely sent off: 2 out of 2 bytes
< HTTP/1.1 403 Forbidden
HTTP/1.1 403 Forbidden
< Server: Cowboy
Server: Cowboy
< Connection: keep-alive
Connection: keep-alive
< Date: Tue, 16 May 2017 14:16:27 GMT
Date: Tue, 16 May 2017 14:16:27 GMT
< Content-Type: text/html;charset=iso-8859-1
Content-Type: text/html;charset=iso-8859-1
< Cache-Control: must-revalidate,no-cache,no-store
Cache-Control: must-revalidate,no-cache,no-store
< Content-Length: 236
Content-Length: 236
< Via: 1.1 vegur
Via: 1.1 vegur

<
<html>
<head>
<meta http-equiv="Content-Type" content="text/html;charset=utf-8"/>
<title>Error 403 Forbidden</title>
</head>
<body><h2>HTTP ERROR 403</h2>
<p>Problem accessing /bots. Reason:
<pre>    Forbidden</pre></p>
</body>
</html>
* Connection #0 to host safe-reef-88300.herokuapp.com left intact

This is expectable as I don't have the token. Can you verify that you have the correct token set in your yaml

Thanks

dkovacevic avatar May 16 '17 14:05 dkovacevic

I had double checked that couple of times, I've had the right token the entire time. However I tried your request with the proper token and got an interesting stack trace:

2017-05-16T14:22:29.979186+00:00 app[web.1]: ERROR [2017-05-16 14:22:29,978] io.dropwizard.jersey.errors.LoggingExceptionMapper: Error handling a request: 1ca95714c56ec966
2017-05-16T14:22:29.979199+00:00 app[web.1]: ! java.lang.NullPointerException: null
2017-05-16T14:22:29.979200+00:00 app[web.1]: ! at com.wire.bots.echo.MessageHandler.onNewBot(MessageHandler.java:62)
2017-05-16T14:22:29.979202+00:00 app[web.1]: ! at com.wire.bots.sdk.server.resources.BotsResource.newBot(BotsResource.java:58)
2017-05-16T14:22:29.979203+00:00 app[web.1]: ! at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2017-05-16T14:22:29.979203+00:00 app[web.1]: ! at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
2017-05-16T14:22:29.979204+00:00 app[web.1]: ! at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2017-05-16T14:22:29.979205+00:00 app[web.1]: ! at java.lang.reflect.Method.invoke(Method.java:498)
2017-05-16T14:22:29.979206+00:00 app[web.1]: ! at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)
2017-05-16T14:22:29.979206+00:00 app[web.1]: ! at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144)
2017-05-16T14:22:29.979207+00:00 app[web.1]: ! at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161)
2017-05-16T14:22:29.979208+00:00 app[web.1]: ! at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:160)
2017-05-16T14:22:29.979209+00:00 app[web.1]: ! at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99)
2017-05-16T14:22:29.979210+00:00 app[web.1]: ! at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389)
2017-05-16T14:22:29.979210+00:00 app[web.1]: ! at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347)
2017-05-16T14:22:29.979211+00:00 app[web.1]: ! at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102)
2017-05-16T14:22:29.979211+00:00 app[web.1]: ! at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:326)
2017-05-16T14:22:29.979212+00:00 app[web.1]: ! at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)
2017-05-16T14:22:29.979212+00:00 app[web.1]: ! at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)
2017-05-16T14:22:29.979213+00:00 app[web.1]: ! at org.glassfish.jersey.internal.Errors.process(Errors.java:315)
2017-05-16T14:22:29.979213+00:00 app[web.1]: ! at org.glassfish.jersey.internal.Errors.process(Errors.java:297)
2017-05-16T14:22:29.979213+00:00 app[web.1]: ! at org.glassfish.jersey.internal.Errors.process(Errors.java:267)
2017-05-16T14:22:29.979214+00:00 app[web.1]: ! at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)
2017-05-16T14:22:29.979214+00:00 app[web.1]: ! at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305)
2017-05-16T14:22:29.979215+00:00 app[web.1]: ! at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154)
2017-05-16T14:22:29.979215+00:00 app[web.1]: ! at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473)
2017-05-16T14:22:29.979216+00:00 app[web.1]: ! at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427)
2017-05-16T14:22:29.979216+00:00 app[web.1]: ! at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388)
2017-05-16T14:22:29.979216+00:00 app[web.1]: ! at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341)
2017-05-16T14:22:29.979217+00:00 app[web.1]: ! at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228)
2017-05-16T14:22:29.979217+00:00 app[web.1]: ! at io.dropwizard.jetty.NonblockingServletHolder.handle(NonblockingServletHolder.java:49)
2017-05-16T14:22:29.979217+00:00 app[web.1]: ! at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1689)
2017-05-16T14:22:29.979218+00:00 app[web.1]: ! at io.dropwizard.servlets.ThreadNameFilter.doFilter(ThreadNameFilter.java:34)
2017-05-16T14:22:29.979218+00:00 app[web.1]: ! at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1676)
2017-05-16T14:22:29.979218+00:00 app[web.1]: ! at io.dropwizard.jersey.filter.AllowedMethodsFilter.handle(AllowedMethodsFilter.java:50)
2017-05-16T14:22:29.979219+00:00 app[web.1]: ! at io.dropwizard.jersey.filter.AllowedMethodsFilter.doFilter(AllowedMethodsFilter.java:44)
2017-05-16T14:22:29.979219+00:00 app[web.1]: ! at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1676)
2017-05-16T14:22:29.979219+00:00 app[web.1]: ! at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:581)
2017-05-16T14:22:29.979220+00:00 app[web.1]: ! at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1174)
2017-05-16T14:22:29.979220+00:00 app[web.1]: ! at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:511)
2017-05-16T14:22:29.979220+00:00 app[web.1]: ! at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1106)
2017-05-16T14:22:29.979221+00:00 app[web.1]: ! at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
2017-05-16T14:22:29.979221+00:00 app[web.1]: ! at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
2017-05-16T14:22:29.979221+00:00 app[web.1]: ! at com.codahale.metrics.jetty9.InstrumentedHandler.handle(InstrumentedHandler.java:240)
2017-05-16T14:22:29.979222+00:00 app[web.1]: ! at io.dropwizard.jetty.RoutingHandler.handle(RoutingHandler.java:51)
2017-05-16T14:22:29.979225+00:00 app[web.1]: ! at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:396)
2017-05-16T14:22:29.979226+00:00 app[web.1]: ! at io.dropwizard.jetty.BiDiGzipHandler.handle(BiDiGzipHandler.java:68)
2017-05-16T14:22:29.979226+00:00 app[web.1]: ! at org.eclipse.jetty.server.handler.RequestLogHandler.handle(RequestLogHandler.java:56)
2017-05-16T14:22:29.979226+00:00 app[web.1]: ! at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:169)
2017-05-16T14:22:29.979227+00:00 app[web.1]: ! at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
2017-05-16T14:22:29.979227+00:00 app[web.1]: ! at org.eclipse.jetty.server.Server.handle(Server.java:524)
2017-05-16T14:22:29.979227+00:00 app[web.1]: ! at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:319)
2017-05-16T14:22:29.979228+00:00 app[web.1]: ! at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:253)
2017-05-16T14:22:29.979228+00:00 app[web.1]: ! at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
2017-05-16T14:22:29.979228+00:00 app[web.1]: ! at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
2017-05-16T14:22:29.979229+00:00 app[web.1]: ! at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
2017-05-16T14:22:29.979229+00:00 app[web.1]: ! at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
2017-05-16T14:22:29.979230+00:00 app[web.1]: ! at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
2017-05-16T14:22:29.979230+00:00 app[web.1]: ! at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
2017-05-16T14:22:29.979230+00:00 app[web.1]: ! at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671)
2017-05-16T14:22:29.979231+00:00 app[web.1]: ! at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589)
2017-05-16T14:22:29.979231+00:00 app[web.1]: ! at java.lang.Thread.run(Thread.java:745)

Line 62 of MessageHandler is here. I'm not confident enough to guess why that is occurring, but I'll try to investigate it some as well.

I also saw your requests, but those errors related to having the wrong auth token (as one would expect).

DonyorM avatar May 16 '17 14:05 DonyorM

This error stack is expectable as you are passing an empty JSON. However Wire Backend is passing the full JSON and you should not see this error. I am puzzled why you don't see POST /bots from Wire BE when you add the bot into conv (or you click on the invite link: https://app.wire.com/?bot=testbridge). Every time you add the bot into conversation backend will call your webhook and you should see that in logs. I think we still have some issues with TLS there (heroku has it)

dkovacevic avatar May 16 '17 14:05 dkovacevic

I'm not seeing anything in the logs when I use the invite link. And yeah Heroku seems to be the issue, I'll have to see if different configurations work better.

DonyorM avatar May 16 '17 14:05 DonyorM

OK. I have checked the Wire BE logs now and I see: PinFingerprintMismatch This is most likely keystore.jks and pubkey.pem mismatch issue

dkovacevic avatar May 16 '17 14:05 dkovacevic

Ok, I'll see if I can fix that. I must have deleted the pub key without deleting the keystore. Not sure when that would have happened.

DonyorM avatar May 16 '17 14:05 DonyorM