Return-Path: X-Original-To: archive-asf-public-internal@cust-asf2.ponee.io Delivered-To: archive-asf-public-internal@cust-asf2.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by cust-asf2.ponee.io (Postfix) with ESMTP id C9CFB2004C8 for ; Mon, 9 May 2016 09:48:14 +0200 (CEST) Received: by cust-asf.ponee.io (Postfix) id C8A451601D4; Mon, 9 May 2016 07:48:14 +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 E301F16098A for ; Mon, 9 May 2016 09:48:13 +0200 (CEST) Received: (qmail 31227 invoked by uid 500); 9 May 2016 07:48:13 -0000 Mailing-List: contact issues-help@activemq.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@activemq.apache.org Delivered-To: mailing list issues@activemq.apache.org Received: (qmail 31054 invoked by uid 99); 9 May 2016 07:48:13 -0000 Received: from arcas.apache.org (HELO arcas) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 09 May 2016 07:48:13 +0000 Received: from arcas.apache.org (localhost [127.0.0.1]) by arcas (Postfix) with ESMTP id F19DD2C1F61 for ; Mon, 9 May 2016 07:48:12 +0000 (UTC) Date: Mon, 9 May 2016 07:48:12 +0000 (UTC) From: "Johan Carlquist (JIRA)" To: issues@activemq.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Created] (AMQ-6283) NC of network of brokers won't reconnect after broken pipe MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 archived-at: Mon, 09 May 2016 07:48:14 -0000 Johan Carlquist created AMQ-6283: ------------------------------------ Summary: NC of network of brokers won't reconnect after broken pipe Key: AMQ-6283 URL: https://issues.apache.org/jira/browse/AMQ-6283 Project: ActiveMQ Issue Type: Bug Components: Broker, networkbridge Affects Versions: 5.13.0 Environment: # lsb_release -a No LSB modules are available. Distributor ID: Ubuntu Description: Ubuntu 14.04.4 LTS Release: 14.04 Codename: trusty # /local/jdk/bin/java -version java version "1.8.0_45" Java(TM) SE Runtime Environment (build 1.8.0_45-b14) Java HotSpot(TM) 64-Bit Server VM (build 25.45-b02, mixed mode) Reporter: Johan Carlquist After mq01 got disconnected due to broken pipe it refused to reconnect because mq02 thinks it already has an outbound connection with mq01. Mq01 logs: {code} May 6 12:41:31 localhost {"timeMillis": 1462531291674,"thread":"ActiveMQ Transport: ssl://esb-prod-mq02.it.su.se/77.238.36.100:61616","level":"INFO","loggerName":"org.apache.activemq.network.DemandForwardingBridgeSupport","message":"Network connection between vm://esb-prod-mq01.it.su.se#10 and ssl://esb-prod-mq02.it.su.se/77.238.36.100:61616 shutdown due to a local error: org.apache.activemq.transport.TransportDisposedIOException: Disposed due to prior exception","endOfBatch":false,"loggerFqcn":"org.slf4j.impl.Log4jLoggerAdapter"} May 6 12:41:31 localhost {"timeMillis": 1462531291675,"thread":"ActiveMQ Transport: ssl://esb-prod-mq02.it.su.se/77.238.36.100:61616","level":"INFO","loggerName":"org.apache.activemq.network.DemandForwardingBridgeSupport","message":"Network connection between vm://esb-prod-mq01.it.su.se#10 and ssl://esb-prod-mq02.it.su.se/77.238.36.100:61616 shutdown due to a local error: org.apache.activemq.transport.TransportDisposedIOException: Disposed due to prior exception","endOfBatch":false,"loggerFqcn":"org.slf4j.impl.Log4jLoggerAdapter"} May 6 12:41:31 localhost {"timeMillis": message repeated 3 times: [1462531291675,"thread":"ActiveMQ Transport: ssl://esb-prod-mq02.it.su.se/77.238.36.100:61616","level":"INFO","loggerName":"org.apache.activemq.network.DemandForwardingBridgeSupport","message":"Network connection between vm://esb-prod-mq01.it.su.se#10 and ssl://esb-prod-mq02.it.su.se/77.238.36.1 00:61616 shutdown due to a local error: org.apache.activemq.transport.TransportDisposedIOException: Disposed due to prior exception","endOfBatch":false,"loggerFqcn":"org.slf4j.impl.Log4jLoggerAdapter"}] May 6 12:41:31 localhost {"timeMillis": 1462531291674,"thread":"ActiveMQ BrokerService[esb-prod-mq01.it.su.se] Task-5014","level":"WARN","loggerName":"org.apache.activemq.network.DemandForwardingBridgeSupport","message":"Caught an exception processing local command","thrown":{"commonElementCount":0,"localizedMessage":"Broken pipe","message":"Broken pipe","name ":"java.net.SocketException","extendedStackTrace":[{"class":"java.net.SocketOutputStream","method":"socketWrite0","file":"SocketOutputStream.java","line":-2,"exact":false,"location":"?","version":"1.8.0_45"},{"class":"java.net.SocketOutputStream","method":"socketWrite","file":"SocketOutputStream.java","line":109,"exact":false,"location":"?","version":"1.8.0_45" },{"class":"java.net.SocketOutputStream","method":"write","file":"SocketOutputStream.java","line":153,"exact":false,"location":"?","version":"1.8.0_45"},{"class":"sun.security.ssl.OutputRecord","method":"writeBuffer","file":"OutputRecord.java","line":431,"exact":false,"location":"?","version":"1.8.0_45"},{"class":"sun.security.ssl.OutputRecord","method":"write" ,"file":"OutputRecord.java","line":417,"exact":false,"location":"?","version":"1.8.0_45"},{"class":"sun.security.ssl.SSLSocketImpl","method":"writeRecordInternal","file":"SSLSocketImpl.java","line":864,"exact":false,"location":"?","version":"1.8.0_45"},{"class":"sun.security.ssl.SSLSocketImpl","method":"writeRecord","file":"SSLSocketImpl.java","line":835,"exact ":false,"location":"?","version":"1.8.0_45"},{"class":"sun.security.ssl.AppOutputStream","method":"write","file":"AppOutputStream.java","line":123,"exact":false,"location":"?","version":"1.8.0_45"},{"class":"org.apache.activemq.transport.tcp.TcpBufferedOutputStream","method":"flush","file":"TcpBufferedOutputStream.java","line":115,"exact":false,"location":"acti vemq-client-5.13.0.jar","version":"5.13.0"},{"class":"java.io.DataOutputStream","method":"flush","file":"DataOutputStream.java","line":123,"exact":false,"location":"?","version":"1.8.0_45"},{"class":"org.apache.activemq.transport.tcp.TcpTransport","method":"oneway","file":"TcpTransport.java","line":194,"exact":false,"location":"activemq-client-5.13.0.jar","vers ion":"5.13.0"},{"class":"org.apache.activemq.transport.AbstractInactivityMonitor","method":"doOnewaySend","file":"AbstractInactivityMonitor.java","line":334,"exact":false,"location":"activemq-client-5.13.0.jar","version":"5.13.0"},{"class":"org.apache.activemq.transport.AbstractInactivityMonitor","method":"oneway","file":"AbstractInactivityMonitor.java","line": 316,"exact":false,"location":"activemq-client-5.13.0.jar","version":"5.13.0"},{"class":"org.apache.activemq.transport.TransportFilter","method":"oneway","file":"TransportFilter.java","line":85,"exact":false,"location":"activemq-client-5.13.0.jar","version":"5.13.0"},{"class":"org.apache.activemq.transport.WireFormatNegotiator","method":"oneway","file":"WireForm atNegotiator.java","line":116,"exact":false,"location":"activemq-client-5.13.0.jar","version":"5.13.0"},{"class":"org.apache.activemq.transport.MutexTransport","method":"oneway","file":"MutexTransport.java","line":68,"exact":false,"location":"activemq-client-5.13.0.jar","version":"5.13.0"},{"class":"org.apache.activemq.transport.ResponseCorrelator","method":"as yncRequest","file":"ResponseCorrelator.java","line":81,"exact":false,"location":"activemq-client-5.13.0.jar","version":"5.13.0"},{"class":"org.apache.activemq.network.DemandForwardingBridgeSupport","method":"serviceLocalCommand","file":"DemandForwardingBridgeSupport.java","line":1009,"exact":true,"location":"activemq-broker-5.13.0.jar","version":"5.13.0"},{"cla ss":"org.apache.activemq.network.DemandForwardingBridgeSupport$2","method":"onCommand","file":"DemandForwardingBridgeSupport.java","line":207,"exact":true,"location":"activemq-broker-5.13.0.jar","version":"5.13.0"},{"class":"org.apache.activemq.transport.ResponseCorrelator","method":"onCommand","file":"ResponseCorrelator.java","line":116,"exact":true,"location" :"activemq-client-5.13.0.jar","version":"5.13.0"},{"class":"org.apache.activemq.transport.MutexTransport","method":"onCommand","file":"MutexTransport.java","line":50,"exact":true,"location":"activemq-client-5.13.0.jar","version":"5.13.0"},{"class":"org.apache.activemq.transport.vm.VMTransport","method":"doDispatch","file":"VMTransport.java","line":162,"exact":t rue,"location":"activemq-broker-5.13.0.jar","version":"5.13.0"},{"class":"org.apache.activemq.transport.vm.VMTransport","method":"dispatch","file":"VMTransport.java","line":154,"exact":true,"location":"activemq-broker-5.13.0.jar","version":"5.13.0"},{"class":"org.apache.activemq.transport.vm.VMTransport","method":"oneway","file":"VMTransport.java","line":131,"e xact":true,"location":"activemq-broker-5.13.0.jar","version":"5.13.0"},{"class":"org.apache.activemq.transport.MutexTransport","method":"oneway","file":"MutexTransport.java","line":68,"exact":true,"location":"activemq-client-5.13.0.jar","version":"5.13.0"},{"class":"org.apache.activemq.transport.ResponseCorrelator","method":"oneway","file":"ResponseCorrelator.j ava","line":60,"exact":true,"location":"activemq-client-5.13.0.jar","version":"5.13.0"},{"class":"org.apache.activemq.broker.TransportConnection","method":"dispatch","file":"TransportConnection.java","line":1433,"exact":true,"location":"activemq-broker-5.13.0.jar","version":"5.13.0"},{"class":"org.apache.activemq.broker.TransportConnection","method":"processDis patch","file":"TransportConnection.java","line":947,"exact":true,"location":"activemq-broker-5.13.0.jar","version":"5.13.0"},{"class":"org.apache.activemq.broker.TransportConnection","method":"iterate","file":"TransportConnection.java","line":993,"exact":true,"location":"activemq-broker-5.13.0.jar","version":"5.13.0"},{"class":"org.apache.activemq.thread.Pooled TaskRunner","method":"runTask","file":"PooledTaskRunner.java","line":133,"exact":true,"location":"activemq-client-5.13.0.jar","version":"5.13.0"},{"class":"org.apache.activemq.thread.PooledTaskRunner$1","method":"run","file":"PooledTaskRunner.java","line":48,"exact":true,"location":"activemq-client-5.13.0.jar","version":"5.13.0"},{"class":"java.util.concurrent. ThreadPoolExecutor","method":"runWorker","file":"ThreadPoolExecutor.java","line":1142,"exact":true,"location":"?","version":"1.8.0_45"},{"class":"java.util.concurrent.ThreadPoolExecutor$Worker","method":"run","file":"ThreadPoolExecutor.java","line":617,"exact":true,"location":"?","version":"1.8.0_45"},{"class":"java.lang.Thread","method":"run","file":"Thread.ja va","line":745,"exact":true,"location":"?","version":"1.8.0_45"}]},"endOfBatch":false,"loggerFqcn":"org.slf4j.impl.Log4jLoggerAdapter"} May 6 12:41:31 localhost {"timeMillis": 1462531291676,"thread":"ActiveMQ Task-4","level":"INFO","loggerName":"org.apache.activemq.network.DiscoveryNetworkConnector","message":"Establishing network connection from vm://esb-prod-mq01.it.su.se?async=false to ssl://esb-prod-mq02.it.su.se:61616","endOfBatch":false,"loggerFqcn":"org.slf4j.impl.Log4jLoggerAdapter"} May 6 12:41:31 localhost {"timeMillis": 1462531291729,"thread":"ActiveMQ BrokerService[esb-prod-mq01.it.su.se] Task-5125","level":"INFO","loggerName":"org.apache.activemq.network.DemandForwardingBridgeSupport","message":"esb-prod-mq01.it.su.se bridge to esb-prod-mq02.it.su.se stopped","endOfBatch":false,"loggerFqcn":"org.slf4j.impl.Log4jLoggerAdapter"} May 6 12:41:31 localhost {"timeMillis": 1462531291819,"thread":"triggerStartAsyncNetworkBridgeCreation: remoteBroker=ssl://esb-prod-mq02.it.su.se/77.238.36.100:61616, localBroker= vm://esb-prod-mq01.it.su.se#12","level":"INFO","loggerName":"org.apache.activemq.network.DemandForwardingBridgeSupport","message":"Network connection between vm://esb-prod-mq01.it.su .se#12 and ssl://esb-prod-mq02.it.su.se/77.238.36.100:61616 (esb-prod-mq02.it.su.se) has been established.","endOfBatch":false,"loggerFqcn":"org.slf4j.impl.Log4jLoggerAdapter"} May 6 12:41:31 localhost {"timeMillis": 1462531291849,"thread":"ActiveMQ Transport: ssl://esb-prod-mq02.it.su.se/77.238.36.100:61616","level":"WARN","loggerName":"org.apache.activemq.network.DemandForwardingBridgeSupport","message":"Network connection between vm://esb-prod-mq01.it.su.se#12 and ssl://esb-prod-mq02.it.su.se/77.238.36.100:61616 shutdown due to a remote error: javax.jms.InvalidClientIDException: Broker: esb-prod-mq02.it.su.se - Client: NC_esb-prod-mq01.it.su.se_outbound already connected from tcp://77.238.36.99:33618","endOfBatch":false,"loggerFqcn":"org.slf4j.impl.Log4jLoggerAdapter"} May 6 12:41:31 localhost {"timeMillis": 1462531291860,"thread":"ActiveMQ BrokerService[esb-prod-mq01.it.su.se] Task-5125","level":"INFO","loggerName":"org.apache.activemq.network.DemandForwardingBridgeSupport","message":"esb-prod-mq01.it.su.se bridge to esb-prod-mq02.it.su.se stopped","endOfBatch":false,"loggerFqcn":"org.slf4j.impl.Log4jLoggerAdapter"} May 6 12:41:32 localhost {"timeMillis": 1462531292849,"thread":"ActiveMQ Task-4","level":"INFO","loggerName":"org.apache.activemq.network.DiscoveryNetworkConnector","message":"Establishing network connection from vm://esb-prod-mq01.it.su.se?async=false to ssl://esb-prod-mq02.it.su.se:61616","endOfBatch":false,"loggerFqcn":"org.slf4j.impl.Log4jLoggerAdapter"} {code} mq02 logs: {code} May 6 12:41:31 localhost {"timeMillis": 1462531291836,"thread":"ActiveMQ NIO Worker 7878","level":"WARN","loggerName":"org.apache.activemq.broker.TransportConnection","message":"Failed to add Connection esb-prod-mq01.it.su.se->esb-prod-mq02.it.su.se-54927-1461934227469-14:2 due to javax.jms.InvalidClientIDException: Broker: esb-prod-mq02.it.su.se - Client: NC_esb-prod-mq01.it.su.se_outbound already connected from tcp://77.238.36.99:33618","endOfBatch":false,"loggerFqcn":"org.slf4j.impl.Log4jLoggerAdapter"} May 6 12:41:31 localhost {"timeMillis": 1462531291836,"thread":"ActiveMQ NIO Worker 7878","level":"WARN","loggerName":"org.apache.activemq.broker.TransportConnection.Service","message":"Async error occurred: javax.jms.InvalidClientIDException: Broker: esb-prod-mq02.it.su.se - Client: NC_esb-prod-mq01.it.su.se_outbound already connected from tcp://77.238.36.99:33618","endOfBatch":false,"loggerFqcn":"org.slf4j.impl.Log4jLoggerAdapter"} May 6 12:41:31 localhost {"timeMillis": 1462531291840,"thread":"ActiveMQ NIO Worker 7878","level":"WARN","loggerName":"org.apache.activemq.broker.TransportConnection.Service","message":"Async error occurred: java.lang.IllegalStateException: Cannot add a producer to a connection that had not been registered: esb-prod-mq01.it.su.se->esb-prod-mq02.it.su.se-54927-1461934227469-14:2","endOfBatch":false,"loggerFqcn":"org.slf4j.impl.Log4jLoggerAdapter"} May 6 12:41:31 localhost {"timeMillis": 1462531291840,"thread":"ActiveMQ NIO Worker 7878","level":"WARN","loggerName":"org.apache.activemq.broker.TransportConnection.Service","message":"Async error occurred: java.lang.IllegalStateException: Cannot add a consumer to a connection that had not been registered: esb-prod-mq01.it.su.se->esb-prod-mq02.it.su.se-54927-1461934227469-14:2","endOfBatch":false,"loggerFqcn":"org.slf4j.impl.Log4jLoggerAdapter"} May 6 15:27:20 localhost {"timeMillis": 1462541240779,"thread":"ActiveMQ Transport: ssl://esb-prod-mq01.it.su.se/77.238.36.99:61616","level":"WARN","loggerName":"org.apache.activemq.network.DemandForwardingBridgeSupport","message":"Network connection between vm://esb-prod-mq02.it.su.se#0 and ssl://esb-prod-mq01.it.su.se/77.238.36.99:61616 shutdown due to a remote error: java.io.EOFException","endOfBatch":false,"loggerFqcn":"org.slf4j.impl.Log4jLoggerAdapter"} {code} Last log line appeared after rebooting mq01. -- This message was sent by Atlassian JIRA (v6.3.4#6332)