From users-return-21709-archive-asf-public=cust-asf.ponee.io@qpid.apache.org Thu Dec 3 16:37:49 2020 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mxout1-he-de.apache.org (mxout1-he-de.apache.org [95.216.194.37]) by mx-eu-01.ponee.io (Postfix) with ESMTPS id C3514180634 for ; Thu, 3 Dec 2020 17:37:49 +0100 (CET) Received: from mail.apache.org (mailroute1-lw-us.apache.org [207.244.88.153]) by mxout1-he-de.apache.org (ASF Mail Server at mxout1-he-de.apache.org) with SMTP id 071B268014 for ; Thu, 3 Dec 2020 16:37:27 +0000 (UTC) Received: (qmail 26818 invoked by uid 500); 3 Dec 2020 16:37:27 -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 26806 invoked by uid 99); 3 Dec 2020 16:37:26 -0000 Received: from spamproc1-he-fi.apache.org (HELO spamproc1-he-fi.apache.org) (95.217.134.168) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 03 Dec 2020 16:37:26 +0000 Received: from localhost (localhost [127.0.0.1]) by spamproc1-he-fi.apache.org (ASF Mail Server at spamproc1-he-fi.apache.org) with ESMTP id 254E2BFD6E for ; Thu, 3 Dec 2020 16:37:26 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamproc1-he-fi.apache.org X-Spam-Flag: NO X-Spam-Score: -0.101 X-Spam-Level: X-Spam-Status: No, score=-0.101 tagged_above=-999 required=6.31 tests=[DKIM_SIGNED=0.1, DKIM_VALID=-0.1, DKIM_VALID_AU=-0.1, DKIM_VALID_EF=-0.1, RCVD_IN_MSPIKE_H2=-0.001, SPF_PASS=-0.001, URIBL_BLOCKED=0.001, URI_HEX=0.1] autolearn=disabled Authentication-Results: spamproc1-he-fi.apache.org (amavisd-new); dkim=pass (2048-bit key) header.d=gmail.com Received: from mx1-ec2-va.apache.org ([116.203.227.195]) by localhost (spamproc1-he-fi.apache.org [95.217.134.168]) (amavisd-new, port 10024) with ESMTP id OXsgPgQSxui4 for ; Thu, 3 Dec 2020 16:37:25 +0000 (UTC) Received-SPF: Pass (mailfrom) identity=mailfrom; client-ip=209.85.167.194; helo=mail-oi1-f194.google.com; envelope-from=robbie.gemmell@gmail.com; receiver= Received: from mail-oi1-f194.google.com (mail-oi1-f194.google.com [209.85.167.194]) by mx1-ec2-va.apache.org (ASF Mail Server at mx1-ec2-va.apache.org) with ESMTPS id 91AD7BCBC6 for ; Thu, 3 Dec 2020 16:37:24 +0000 (UTC) Received: by mail-oi1-f194.google.com with SMTP id l200so2779780oig.9 for ; Thu, 03 Dec 2020 08:37:24 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:references:in-reply-to:from:date:message-id:subject:to; bh=zRtD6NKy8OFo8QFTnGRCJUguv4y7nEOJnhG0yfbHzMw=; b=mp2cNn5Jtnjf1xLZl0s7j7l7TJ8xn5bkCqPdRpBmPcaYwSIwkcEoypEf5B/UMe5mOm BSd9Gr4R7xhqKpfuwkRPWltGlhCKEtWxrxfZ5uZrH7MTDlmtM2eRqA+qP9XTin1EEqdc 74Dy2QNeQjV+7Is+B255AxDPTLi/cIPvypf67vzV0EkDWfamkV+4sDct0Jet6UpGybZC Zi+l5qGfbljvl5qCnon9SWzZ2rPKdWBuw3lfrbiuYMuJvmsAHVi0jnX4UqTdxoN7pJQp hY359Qwx9+way0PE9CmIFcPoGJH1g+c+pwPNgoJL8wn2iDxLwOO+m3QUGkIk+5oNIO+G Q93g== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to; bh=zRtD6NKy8OFo8QFTnGRCJUguv4y7nEOJnhG0yfbHzMw=; b=AWUqMlZSi/7FDBlu3zsQRavgt6+a8x2pbGGE2HzMyIUmXbxAiT2/M3Ly71LOAoehsE 7H81sFAhG+zXaxP5f1cLojoelakq0HwnF70WBmq//mPFzkR8iz1Tds60PpZXTHSCO+bp pZrFVo02iOy2sLqg4Wr06dfMBpkxmhG1eRbhLvyJoPa5JYvk4fE2rYh8J2+uRXSgW5E+ QzkOYz6nur1T8d94VdvNm/0lzophreQPrsaZpxZBVECW/AZKfG0bxLXGR0j5y0LGcUuW /OYPBDJq5j+06SBFq6kzNwjqDSCU0oOQS1Ar8nwSCKyDs8AC+qMW5B7EYCUFhK3gffoM h6tw== X-Gm-Message-State: AOAM5326T/PoO34mvLXi0TsjgwknTIHvRBAaNAGReHxCIvlVBA+muzw6 qPHM8yM4PtAirVYGeUdQ+NnlPRkSVbnnXAeIfdbB3bi8Qs3cOg== X-Google-Smtp-Source: ABdhPJxWVjZX+gyqXM/WVek1AsKS9t65J61Nq2CvZbzJ9J4ov9vYbBcjGOjuaUm8CsQBDMOJfDoY1r6gGxReg8ST1yA= X-Received: by 2002:aca:c3c3:: with SMTP id t186mr2399218oif.53.1607013443610; Thu, 03 Dec 2020 08:37:23 -0800 (PST) MIME-Version: 1.0 References: <1605201255049-0.post@n2.nabble.com> <1605631282142-0.post@n2.nabble.com> <1606410779172-0.post@n2.nabble.com> <1606921713370-0.post@n2.nabble.com> <1607002315618-0.post@n2.nabble.com> In-Reply-To: <1607002315618-0.post@n2.nabble.com> From: Robbie Gemmell Date: Thu, 3 Dec 2020 16:37:13 +0000 Message-ID: Subject: Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher To: users Content-Type: text/plain; charset="UTF-8" To be clear I meant testing of the issue in question, rather than debugging your application / use of Service Bus. On Thu, 3 Dec 2020 at 13:32, akabhishek1 wrote: > > Hi Robbie, > > Sure, I will be happy to provide you testing feedback. > > I was doing testing with "qpid-jms-client-0.56.0-SNAPSHOT" and > "proton-j-0.33.8". So far I managed to found three issues. > These issues are intermittent, however we can regenerate this issue in > couple of retries. I manage to capture error with Qpid Traces. Please find > below details. > > Infrastructure Details --> Created 2 JMS connection instance for testing. > First JMS connection. > * 1 endpoint topic-subscription > * 4 consumer/listener > > Second JMS connection. > * 1 endpoint Queue > * 4 consumer/listener > > Steps to reproduce this issue - > 1. Start the application, which should start listening on both endpoints > with separate JMS connections > 2. DO NOT publish any message for consumption > 3. Keep Application idle for 5m or sometimes 20m. If you didn't get this > issue then please restart the application couple of times > > **** Issue Details ***** > 1. Both JMS connection have one active listener, but still getting this > error - 'The connection was inactive for more than the allowed 120000 > milliseconds and is closed by container > '7A2E0A0515A9427F82D1ACF7F25A024D_G12'. [condition = > amqp:connection:forced]' - 'class javax.jms.JMSException' > > We shouldn't get this error as we have 1 active listener on both JMS > connection. Please refer "Receiver_Timeout_120000_ms.txt" log file for more > details. > Your logs show there was a consumer and Service Bus closed it, with a rather misleading error description that "The connection was inactive for more than the allowed 120000 milliseconds and is closed...". The connection was not closed (and as a whole wasnt inactive for 120sec either way), the receiver was. ServiceBus has its own unique definitions and enforcements of being idle. ServiceBus closing the consumer link because you aren't using it is not a client issue. > 2. Inconsistent JMS connection status while getting timeout error. > a) Connection Active for Receiver TimeOut - If we are getting timeout > error due to receiver then we can see that connection is active at time of > exception. Refer "Receiver_Timeout_120000_ms.txt" > > b) Connection InActive for No Session/Producer/Consumer - Create a JMS > connection which does not have any session/producer/consumer and keep > application running. We will get 60000ms idle timeout error after some > time. Please refer below logs. > We are using "JmsConnection.getClientID" to check connection status. Please > refer below sample method 'isConnectionActive'. > > Problem - At receiver time out (a) connection is active, But at second > scenario (b) connection is inactive. > I think at both scenario connection should be inactive. > No, they shouldn't. In the first case, the connection was still open as I noted above, hence it didn't behave like it isn't. In the latter case, the connection as a whole got closed, and so reacted accordingly. > ***Logs** > TRACE 2020-12-03 12:40:05,354 [AmqpProvider > :(3):[amqps://***.servicebus.windows.net:-1]] > org.apache.qpid.jms.provider.amqp.FRAMES: [1314740929:0] RECV: > Close{error=Error{condition=amqp:connection:forced, description='The > connection was inactive for more than the allowed 60000 milliseconds and is > closed by container 'LinkTracker'. > TrackingId:8ac03af7d6794026ab3948b199e58a35_G5, SystemTracker:gateway5, > Timestamp:2020-12-03T12:40:05', info=null}} > TRACE 2020-12-03 12:40:05,364 [AmqpProvider > :(3):[amqps://***.servicebus.windows.net:-1]] > org.apache.qpid.jms.provider.amqp.FRAMES: [1314740929:0] SENT: > Close{error=null} > ERROR 2020-12-03 12:40:05,370 [QpidJMS Connection Executor: > ID:a6cf63d9-4608-4643-8955-eee32e604674:1] > org.mule.servicebus.SbusConnector: Connection exception, Reason 'The > connection was inactive for more than the allowed 60000 milliseconds and is > closed by container 'LinkTracker'. > TrackingId:8ac03af7d6794026ab3948b199e58a35_G5, SystemTracker:gateway5, > Timestamp:2020-12-03T12:40:05 [condition = amqp:connection:forced]' - 'class > org.apache.qpid.jms.JmsConnectionRemotelyClosedException', > isConnectionActive 'false' > > ****Sample Code *** > protected boolean isConnectionActive() { > boolean connectionStatus = false; > try { > String clientID = getConnection().getClientID(); > connectionStatus = true; > } catch (Exception e) { > connectionStatus = false; > } > return connectionStatus; > } > > 3. Use Case - We have 1 JMS connection, which will be used for publishing > message. > We know that ServiceBus detach active connection link, if we don't have any > active Producer/Consumer. > For avoiding this issue, we registered a timer which will periodically > create/reset temporary Session+Producer instead of JMS connection. This > solution help us to keep JMS connection live, so we don't need to reset JMS > connection again and again. We haven't faced any issue so far with old > client 0.45.0 jar. > > After upgrading the JAR, we are facing intermittent issue while resetting > Producer. Error Log - "Failed to reset temp producer - > javax.jms.JMSException: The service was unable to process the request;" > Please refer "3rd_issue_Failed_To_Reset_Producer_Error.txt" for more > details. > The server refused the producers link attach, with error indicating an internal-error and description saying it wasnt able to process the request and to try again. I dont see anything wrong in what the client says its doing (which matches what it did previously), and the server gives no useful reason why it failed. This seems like a transient server failure of some kind. > > NOTE - We haven't faced above 3 issues with Old client 0.45.0 jar. > > Could you please advise us on above 3 issues. Please feel free to let me > know for any other information. > > Receiver_Timeout_120000_ms.txt > > 3rd_issue_Failed_To_Reset_Producer_Error.txt > > > > > -- > 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