search

rapidpro / mage

High performance Dropwizard based webserver for receiving incoming messages on behalf of RapidPro
GNU Affero General Public License v3.0
2 stars 8 forks source link

Already connected exception #11

Closed rgaudin closed 7 years ago

rgaudin commented 7 years ago

After setting up a Twitter Channel on rapidpro and starting mage, rapidpro gets to receive the incoming DMs and Follow requests but can't seem to reply through Twitter.

Rapidpro UI indicates the messages have been sent but it's not sent to Twitter. I also noticed the backlog of incoming messages is processed everytime I relaunch mage so it's not marked as processed or something.

mage outputs a Temba API request failed with exception ProcessingException which is not very clear so I've added the stacktrace which indicates the problem is an Already connected exception.

I am using version (tag) 0.1.82

INFO  [2017-03-23 09:40:30,094] org.eclipse.jetty.setuid.SetUIDListener: Opened application@2555fff0{HTTP/1.1}{0.0.0.0:8026}
INFO  [2017-03-23 09:40:30,094] org.eclipse.jetty.setuid.SetUIDListener: Opened admin@70d2e40b{HTTP/1.1}{0.0.0.0:8028}
INFO  [2017-03-23 09:40:30,098] org.eclipse.jetty.server.Server: jetty-9.2.z-SNAPSHOT
INFO  [2017-03-23 09:40:30,231] io.rapidpro.mage.cache.Cache: Created Redis pool (8 max-total, 8 max-idle)
INFO  [2017-03-23 09:40:30,404] io.rapidpro.mage.service.ServiceManager: Created services (user=#6)
INFO  [2017-03-23 09:40:30,404] io.rapidpro.mage.twitter.TwitterManager: Starting Twitter manager node...
INFO  [2017-03-23 09:40:30,478] io.rapidpro.mage.twitter.TwitterManager: Becoming Twitter master node...
INFO  [2017-03-23 09:40:30,506] io.rapidpro.mage.twitter.TwitterManager: Found 1 active Twitter channel(s)
INFO  [2017-03-23 09:40:30,985] io.rapidpro.mage.twitter.TwitterManager: Added Twitter stream for handle XXXX (XXXX) on channel #3
INFO  [2017-03-23 09:40:30,988] io.rapidpro.mage.twitter.TwitterStream: Starting back-fill task for channel #3
INFO  [2017-03-23 09:40:31,259] io.dropwizard.jersey.DropwizardResourceConfig: The following paths were found for the configured resources:

    DELETE  /api/v1/twitter/{uuid} (io.rapidpro.mage.resource.TwitterResource)
    POST    /api/v1/twitter (io.rapidpro.mage.resource.TwitterResource)
    POST    /api/v1/twitter/{uuid} (io.rapidpro.mage.resource.TwitterResource)
    GET     /api/v1/external/{action}/{uuid} (io.rapidpro.mage.resource.ExternalResource)
    POST    /api/v1/external/{action}/{uuid} (io.rapidpro.mage.resource.ExternalResource)
    POST    /api/v1/twilio (io.rapidpro.mage.resource.TwilioResource)
    POST    /api/v1/vumi/{action}/{uuid} (io.rapidpro.mage.resource.VumiResource)

INFO  [2017-03-23 09:40:31,275] org.eclipse.jetty.server.handler.ContextHandler: Started i.d.j.MutableServletContextHandler@12c60152{/,null,AVAILABLE}
INFO  [2017-03-23 09:40:31,289] io.dropwizard.setup.AdminEnvironment: tasks =

    POST    /tasks/sentry-test (io.rapidpro.mage.task.SentryTestTask)
    POST    /tasks/log-level (io.dropwizard.servlets.tasks.LogConfigurationTask)
    POST    /tasks/gc (io.dropwizard.servlets.tasks.GarbageCollectionTask)
    POST    /tasks/twitter-master (io.rapidpro.mage.task.TwitterMasterTask)
    POST    /tasks/twitter-backfill (io.rapidpro.mage.task.TwitterBackfillTask)

INFO  [2017-03-23 09:40:31,303] org.eclipse.jetty.server.handler.ContextHandler: Started i.d.j.MutableServletContextHandler@44a6a68e{/,null,AVAILABLE}
INFO  [2017-03-23 09:40:31,330] org.eclipse.jetty.server.ServerConnector: Started application@2555fff0{HTTP/1.1}{0.0.0.0:8026}
INFO  [2017-03-23 09:40:31,332] org.eclipse.jetty.server.ServerConnector: Started admin@70d2e40b{HTTP/1.1}{0.0.0.0:8028}
INFO  [2017-03-23 09:40:31,333] org.eclipse.jetty.server.Server: Started @3131ms
javax.ws.rs.ProcessingException: Already connectedWARN  [2017-03-23 09:40:31,406] io.rapidpro.mage.temba.TembaManager$RequestProcess: class javax.ws.rs.ProcessingException: Already connected: java.lang.IllegalStateException: Already connected -- javax.ws.rs.ProcessingException: Already connected

    at org.glassfish.jersey.client.ClientRuntime.invoke(ClientRuntime.java:255)
    at org.glassfish.jersey.client.JerseyInvocation$1.call(JerseyInvocation.java:667)
    at org.glassfish.jersey.client.JerseyInvocation$1.call(JerseyInvocation.java:664)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:315)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:297)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:228)
    at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:444)
    at org.glassfish.jersey.client.JerseyInvocation.invoke(JerseyInvocation.java:664)
    at org.glassfish.jersey.client.JerseyInvocation$Builder.method(JerseyInvocation.java:424)
    at org.glassfish.jersey.client.JerseyInvocation$Builder.post(JerseyInvocation.java:333)
    at io.rapidpro.mage.temba.TembaClients$DefaultClient.call(TembaClients.java:57)
    at io.rapidpro.mage.temba.TembaManager$RequestProcess.doUnitOfWork(TembaManager.java:87)
    at io.rapidpro.mage.process.BaseProcess$UnitOfWorkWrapper.run(BaseProcess.java:77)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
    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)
Caused by: java.lang.IllegalStateException: Already connected
    at sun.net.www.protocol.http.HttpURLConnection.setRequestProperty(HttpURLConnection.java:3053)
    at sun.net.www.protocol.https.HttpsURLConnectionImpl.setRequestProperty(HttpsURLConnectionImpl.java:316)
    at org.glassfish.jersey.client.HttpUrlConnector.setOutboundHeaders(HttpUrlConnector.java:364)
    at org.glassfish.jersey.client.HttpUrlConnector.access$100(HttpUrlConnector.java:91)
    at org.glassfish.jersey.client.HttpUrlConnector$4.getOutputStream(HttpUrlConnector.java:327)
    at org.glassfish.jersey.message.internal.CommittingOutputStream.commitStream(CommittingOutputStream.java:201)
    at org.glassfish.jersey.message.internal.CommittingOutputStream.commitStream(CommittingOutputStream.java:195)
    at org.glassfish.jersey.message.internal.CommittingOutputStream.commit(CommittingOutputStream.java:263)
    at org.glassfish.jersey.message.internal.OutboundMessageContext.commitStream(OutboundMessageContext.java:816)
    at org.glassfish.jersey.client.ClientRequest.writeEntity(ClientRequest.java:546)
    at org.glassfish.jersey.client.HttpUrlConnector._apply(HttpUrlConnector.java:331)
    at org.glassfish.jersey.client.HttpUrlConnector.apply(HttpUrlConnector.java:243)
    at org.glassfish.jersey.client.ClientRuntime.invoke(ClientRuntime.java:246)
    ... 19 more
WARN  [2017-03-23 09:40:31,414] io.rapidpro.mage.temba.TembaManager$RequestProcess: Temba API request failed with exception ProcessingException, retrying in 1000 milliseconds
rowanseymour commented 7 years ago

Mage isn't used for sending DMs from RapidPro - for that we just use the Twython client. Maybe you need to check your TWITTER_ settings in RapidPro?

Whenever Mage is launched it has a look for messages it might have missed whilst it was down, but it shouldn't create any duplicates in the database because it can match the external_id field with Twitter's id for each message.

rgaudin commented 7 years ago

OK thanks, I though mage was used for ins and outs. Figured from celery log that I forgot to switched back the SEND_MESSAGES setting to True.

I can now send outgoing DMs and as you said, it doesn't create duplicates.

Do you have any idea regarding this exception though? Should it be ignored?

rowanseymour commented 7 years ago

Sorry really not sure about that exception. TembaManager.RequestProcess is the thread that makes API calls from Mage to RapidPro (e.g. telling RapidPro to handle a DM put in the database by Mage). Maybe something to do with this https://java.net/jira/browse/JERSEY-2729?

rgaudin commented 7 years ago

Ah! So the issue mentioned a relation with SSL handshake. Since I'm testing in https with a self-signed certificate, I figured that could be the problem. After enabling regular http and setting the temba host to it, it works as expected without exception.