From users-return-18201-archive-asf-public=cust-asf.ponee.io@qpid.apache.org Thu Jan 25 11:59:27 2018 Return-Path: X-Original-To: archive-asf-public@eu.ponee.io Delivered-To: archive-asf-public@eu.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by mx-eu-01.ponee.io (Postfix) with ESMTP id 81A6A180651 for ; Thu, 25 Jan 2018 11:59:27 +0100 (CET) Received: by cust-asf.ponee.io (Postfix) id 71D42160C3D; Thu, 25 Jan 2018 10:59:27 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id 8EE30160C13 for ; Thu, 25 Jan 2018 11:59:26 +0100 (CET) Received: (qmail 69051 invoked by uid 500); 25 Jan 2018 10:59:25 -0000 Mailing-List: contact users-help@qpid.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: users@qpid.apache.org Delivered-To: mailing list users@qpid.apache.org Received: (qmail 69024 invoked by uid 99); 25 Jan 2018 10:59:24 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd2-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 25 Jan 2018 10:59:24 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd2-us-west.apache.org (ASF Mail Server at spamd2-us-west.apache.org) with ESMTP id 710901A0C73 for ; Thu, 25 Jan 2018 10:59:24 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd2-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: 1.992 X-Spam-Level: * X-Spam-Status: No, score=1.992 tagged_above=-999 required=6.31 tests=[DKIM_SIGNED=0.1, DKIM_VALID=-0.1, DKIM_VALID_AU=-0.1, KAM_ASCII_DIVIDERS=0.8, RCVD_IN_DNSWL_NONE=-0.0001, RCVD_IN_MSPIKE_H3=-0.01, RCVD_IN_MSPIKE_WL=-0.01, SPF_PASS=-0.001, URI_HEX=1.313] autolearn=disabled Authentication-Results: spamd2-us-west.apache.org (amavisd-new); dkim=pass (2048-bit key) header.d=gmail.com Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd2-us-west.apache.org [10.40.0.9]) (amavisd-new, port 10024) with ESMTP id JxasOyrCeSvi for ; Thu, 25 Jan 2018 10:59:22 +0000 (UTC) Received: from mail-wm0-f45.google.com (mail-wm0-f45.google.com [74.125.82.45]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTPS id F2D455F3BA for ; Thu, 25 Jan 2018 10:59:21 +0000 (UTC) Received: by mail-wm0-f45.google.com with SMTP id x4so30563849wmc.0 for ; Thu, 25 Jan 2018 02:59:21 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:reply-to:in-reply-to:references:from:date:message-id :subject:to; bh=bs6CKL8XlWOCxKJrdaCS6MLF3Va9dd5LOYI5fQx4biI=; b=MbPPCIW5j+DTTE+T+8nFTnWJOBoDwtNNRHKKKuZQUk1a6cxuOKWrD80xosnTOrRyax oRwbx6FXlI9N2N+b20aOkfuOoMwTIm9ZsAZBjoqGbXZQZytbRX2ml6BJevTGVOY2JmUc pOaJeNiH54lU9oOBJo8hg1uWJRgdJ1xvXSz/4V3ZQu11S8w+31FSlkTh8Hmb3gWYZPIW 34JdPH+aTr52PsBqH/HvNReledtJeZoRqPCiQtd0f4/rNjNiLUvGF5oqAQoZSml4dNat Iu1OeVEU7+/zIM9hOCI8TGMi2p1+yDazp81GPODAE8h/wS/66j/M5BkW5+5WHEY0Nsya nVZw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:reply-to:in-reply-to:references :from:date:message-id:subject:to; bh=bs6CKL8XlWOCxKJrdaCS6MLF3Va9dd5LOYI5fQx4biI=; b=ctSuuwO7Tu2gwcNwCdkQ1qv7yoWHBaXmNfCUQv/mycl8g7PZ6VLcLj3tKX7++qNYTT wODS6gA19S1x+NZ70nZxcQkxsmhPfkJAqroaEmoqNGXLnFS4mgldNtcA9fp/VaZv4mav mVBp1ClKOHQBcJJhHywTJcAkaJc6VH/ct4RFDnlb7DioXDw0upxxkX/yDrb8CPx1uKbs xJv1Rf1r4bcW0VBOywwtOd+cCwi73Fwb56QibmC5k9zOgx/rDJpnsnBqTfqfvfMj1ULz thj7pY7Uv/VLVlBf9rGagl0U5XLHaKqR3/ACMhNB1tD9Qs0vbfWo6AcyDYsVBS87OxRJ H2Dg== X-Gm-Message-State: AKwxytdkPykAl4gi0Qrz8/RibjFq3jPhQuIGYNSenLKp8lhaex/iWwJI mwbo4bJSKlu+vRakxp580FQ7LaBHzvD9rx6QIV2MFw9k X-Google-Smtp-Source: AH8x227N9PujcBE7chTp5IAkOAPyVz1KNF3JjX1k/WXE8OSE3ICyZOUFSglIDbqSsqICg/8TvwCXpKg97AROCFmYNu8= X-Received: by 10.28.166.195 with SMTP id p186mr2808622wme.81.1516877960741; Thu, 25 Jan 2018 02:59:20 -0800 (PST) MIME-Version: 1.0 Received: by 10.223.136.229 with HTTP; Thu, 25 Jan 2018 02:59:20 -0800 (PST) Reply-To: keith.wall@gmail.com In-Reply-To: <1516819463727-0.post@n2.nabble.com> References: <1516819463727-0.post@n2.nabble.com> From: Keith W Date: Thu, 25 Jan 2018 10:59:20 +0000 Message-ID: Subject: Re: JMS Client failover error stops message consumption To: users@qpid.apache.org Content-Type: text/plain; charset="UTF-8" Bryan I haven't seen failover exhibit this problem before. The reconnection logic awaits the dispatcher (a session scoped thread which invokes your message listen) to finish delivery of the last message to your application before completing the reconnection. The dispatcher close allows a period of 1000ms for the dispatcher to complete its work before timing out. You could try increasing the timeout (system property -DDISPATCHER_SHUTDOWN_TIMEOUT_MS=). However, as you say you message listener does not more than log a message I suspect there might be something else going on. If increasing the timeout doesn't help, share a complete log captured at DEBUG level and I'll try and help further. HTH Keith. On 24 January 2018 at 18:44, bryand wrote: > I'm using broker-j-7.0.0 and apache-qpid-jms-0-x-6.3.0. For broker-j I have > HA setup with 3 brokers and have been testing failover by simply starting > and stopping the virtual host node on a random broker. Usually failover on > my simple JMS message consumer is successful and message consumption > continues but occasionally I'll receive the following exception on my > consumer and it no longer receives messages: > java.lang.RuntimeException: Dispatcher did not close down within the timeout > of 1000 ms. > > My simple java client code is this.. > > String brokerUrl = > "amqp:///spgqpiddev?failover='roundrobin?cyclecount='2''&brokerlist='tcp://spgappdevmutil:5672?retries='3'&connectdelay='1000';tcp://appprd02:5672?retries='3'&connectdelay='1000';tcp://appprd02:5682?retries='3'&connectdelay='1000''"; > > ConnectionFactory connectionFactory = new AMQConnectionFactory(brokerUrl); > > String user = "appuser"; > String pwd = "xxxx"; > > Connection connection = connectionFactory.createConnection(user, pwd); > > connection.start(); > > Session session = connection.createSession(false, Session.AUTO_ACKNOWLEDGE); > > String queueName = "app_testcluster"; > > Destination destination = AMQDestination.createDestination(queueName, > false); > > MessageConsumer messageConsumer = session.createConsumer(destination); > // this MsgListener class simply prints out messages received. > messageConsumer.setMessageListener(new MsgListener()); > > The full stacktrace is: > count: 500, id: ID:6c8f4df0-c8df-3751-86ee-75cef258de69, ts: 2018-01-24 > 09:58:49.718, lastTimestamp: 1516805929718, body: null > 2018-01-24 13:23:58,820 [10.0.51.42:5672] - ERROR AMQConnectionDelegate_0_10 > - error during failover > org.apache.qpid.transport.ConnectionException: connection closed > at org.apache.qpid.transport.Connection.send(Connection.java:414) > at org.apache.qpid.transport.Session.send(Session.java:588) > at org.apache.qpid.transport.Session.invoke(Session.java:804) > at org.apache.qpid.transport.Session.invoke(Session.java:613) > at > org.apache.qpid.transport.SessionInvoker.sessionAttach(SessionInvoker.java:29) > at org.apache.qpid.transport.Session.attach(Session.java:290) > at org.apache.qpid.transport.Session.resume(Session.java:300) > at org.apache.qpid.transport.Connection.resume(Connection.java:524) > at > org.apache.qpid.client.AMQConnectionDelegate_0_10.resubscribeSessions(AMQConnectionDelegate_0_10.java:288) > at > org.apache.qpid.client.AMQConnection.resubscribeSessions(AMQConnection.java:1480) > at > org.apache.qpid.client.AMQConnectionDelegate_0_10$2.run(AMQConnectionDelegate_0_10.java:363) > at > org.apache.qpid.client.AMQConnection.doWithAllLocks(AMQConnection.java:1959) > at > org.apache.qpid.client.AMQConnection.doWithAllLocks(AMQConnection.java:1947) > at > org.apache.qpid.client.AMQConnection.doWithAllLocks(AMQConnection.java:1926) > at > org.apache.qpid.client.AMQConnectionDelegate_0_10.closed(AMQConnectionDelegate_0_10.java:340) > at org.apache.qpid.transport.Connection.closed(Connection.java:601) > at org.apache.qpid.transport.network.Assembler.closed(Assembler.java:113) > at > org.apache.qpid.transport.network.InputHandler.closed(InputHandler.java:219) > at org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:225) > at java.lang.Thread.run(Thread.java:745) > 2018-01-24 13:23:58,822 [10.1.1.119:5682] - INFO FailoverRoundRobinServers > - ==== Checking failoverAllowed() ==== > 2018-01-24 13:23:58,822 [10.1.1.119:5682] - INFO FailoverRoundRobinServers > - Cycle Servers: > Cycle Retries:2 > Current Cycle:0 > Server Retries:3 > Current Retry:0 > Current Broker:2 > tcp://spgappdevmutil:5672?connectdelay='1000'&retries='3' > tcp://appprd02:5672?connectdelay='1000'&retries='3' >>tcp://appprd02:5682?connectdelay='1000'&retries='3' > > 2018-01-24 13:23:58,822 [10.1.1.119:5682] - INFO FailoverRoundRobinServers > - ==================================== > 2018-01-24 13:23:58,822 [10.1.1.119:5682] - INFO FailoverRoundRobinServers > - Trying tcp://appprd02:5682?connectdelay='1000'&retries='3' > 2018-01-24 13:23:58,823 [10.1.1.119:5682] - INFO FailoverRoundRobinServers > - Delay between connect retries:1000 > 2018-01-24 13:23:59,826 [10.0.51.42:5672] - ERROR > oggingUncaughtExceptionHandler - Uncaught exception in thread > "IoRcvr-/10.240.15.7:65068-spgappdevmutil/10.0.51.42:5672" > java.lang.RuntimeException: Dispatcher did not close down within the timeout > of 1000 ms. > at org.apache.qpid.client.AMQSession$Dispatcher.close(AMQSession.java:3407) > at > org.apache.qpid.client.AMQSession.markClosedConsumers(AMQSession.java:3047) > at > org.apache.qpid.client.AMQSession.markClosedProducersAndConsumers(AMQSession.java:3077) > at org.apache.qpid.client.AMQSession.markClosed(AMQSession.java:2278) > at > org.apache.qpid.client.AMQConnectionDelegate_0_10.closed(AMQConnectionDelegate_0_10.java:392) > at org.apache.qpid.transport.Connection.closed(Connection.java:601) > at org.apache.qpid.transport.network.Assembler.closed(Assembler.java:113) > at > org.apache.qpid.transport.network.InputHandler.closed(InputHandler.java:219) > at org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:225) > at java.lang.Thread.run(Thread.java:745) > Exception in thread > "IoRcvr-/10.240.15.7:65068-spgappdevmutil/10.0.51.42:5672" > java.lang.RuntimeException: Dispatcher did not close down within the timeout > of 1000 ms. > at org.apache.qpid.client.AMQSession$Dispatcher.close(AMQSession.java:3407) > at > org.apache.qpid.client.AMQSession.markClosedConsumers(AMQSession.java:3047) > at > org.apache.qpid.client.AMQSession.markClosedProducersAndConsumers(AMQSession.java:3077) > at org.apache.qpid.client.AMQSession.markClosed(AMQSession.java:2278) > at > org.apache.qpid.client.AMQConnectionDelegate_0_10.closed(AMQConnectionDelegate_0_10.java:392) > at org.apache.qpid.transport.Connection.closed(Connection.java:601) > at org.apache.qpid.transport.network.Assembler.closed(Assembler.java:113) > at > org.apache.qpid.transport.network.InputHandler.closed(InputHandler.java:219) > at org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:225) > at java.lang.Thread.run(Thread.java:745) > 2018-01-24 13:24:00,198 [10.1.1.119:5682] - INFO AMQConnection > - Cannot connect to broker > (tcp://appprd02:5682?connectdelay='1000'&retries='3'): Virtual host > 'spgqpiddev' is not active:Unable to connect to broker at > tcp://appprd02:5682?connectdelay='1000'&retries='3' > 2018-01-24 13:24:00,198 [10.1.1.119:5682] - INFO FailoverRoundRobinServers > - ==== Checking failoverAllowed() ==== > 2018-01-24 13:24:00,198 [10.1.1.119:5682] - INFO FailoverRoundRobinServers > - Cycle Servers: > > > > > -- > Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html > > --------------------------------------------------------------------- > To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org > For additional commands, e-mail: users-help@qpid.apache.org > --------------------------------------------------------------------- To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org For additional commands, e-mail: users-help@qpid.apache.org