[ARTEMIS-4130] failed amqp connect attempt leads to 3 stack traces in log

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.27.1
• Component/s: AMQP
• Assignee: Unassigned
• Reporter: Erwin Dondorp
• Created: 15/Jan/23 12:59
• Updated: 02/Feb/23 15:04
• Resolved: 31/Jan/23 12:01

Description

context:

• server login.conf allows only "PropertiesLoginModule required" (i.e. username+password only)
• client is using AMQP with Python Proton library
• client is connecting anonymously to this server

the connect attempt is supposed to fail because it is trying anonymous login on a server that does not allow that. but that is not the problem.

instead of a simple rejected login, this results in 3 stack traces in the artemis server logfile per connect attempt. the client still gets its rejection, but in the form of a "amqp:internal-error / Unrecoverable error: NullPointerException".

this is the log for a single connect attempt:

2023-01-15 12:46:35,847 WARN  [org.apache.activemq.artemis.core.server] AMQ222216: Security problem while authenticating: AMQ229031: Unable to validate user from /10.11.1.3:62895. Username: null; SSL certificate subject DN: unavailable
2023-01-15 12:46:35,847 WARN  [org.apache.activemq.artemis.protocol.amqp.proton.AMQPConnectionContext] AMQ229031: Unable to validate user from /10.11.1.3:62895. Username: null; SSL certificate subject DN: unavailable
org.apache.activemq.artemis.api.core.ActiveMQSecurityException: AMQ229031: Unable to validate user from /10.11.1.3:62895. Username: null; SSL certificate subject DN: unavailable
        at org.apache.activemq.artemis.core.security.impl.SecurityStoreImpl.authenticationFailed(SecurityStoreImpl.java:360) ~[artemis-server-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.core.security.impl.SecurityStoreImpl.authenticate(SecurityStoreImpl.java:189) ~[artemis-server-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl.validateUser(ActiveMQServerImpl.java:1744) ~[artemis-server-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.AMQPConnectionContext.validateUser(AMQPConnectionContext.java:595) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.AMQPConnectionContext.onRemoteOpen(AMQPConnectionContext.java:553) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.handler.Events.dispatch(Events.java:32) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler.dispatch(ProtonHandler.java:565) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler.flush(ProtonHandler.java:361) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler.inputBuffer(ProtonHandler.java:318) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.AMQPConnectionContext.inputBuffer(AMQPConnectionContext.java:242) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.broker.ActiveMQProtonRemotingConnection.bufferReceived(ActiveMQProtonRemotingConnection.java:134) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.core.remoting.server.impl.RemotingServiceImpl$DelegatingBufferHandler.bufferReceived(RemotingServiceImpl.java:691) ~[artemis-server-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.core.remoting.impl.netty.ActiveMQChannelHandler.channelRead(ActiveMQChannelHandler.java:73) ~[artemis-core-client-2.27.1.jar:2.27.1]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:800) ~[netty-transport-classes-epoll-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:499) ~[netty-transport-classes-epoll-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:397) ~[netty-transport-classes-epoll-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.82.Final.jar:4.1.82.Final]
        at org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run(ActiveMQThreadFactory.java:118) ~[artemis-commons-2.27.1.jar:?]
2023-01-15 12:46:35,848 WARN  [org.apache.activemq.artemis.core.server] AMQ222216: Security problem while authenticating: AMQ229031: Unable to validate user from /10.11.1.3:62895. Username: null; SSL certificate subject DN: unavailable
2023-01-15 12:46:35,848 WARN  [org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler] AMQ229031: Unable to validate user from /10.11.1.3:62895. Username: null; SSL certificate subject DN: unavailable
org.apache.activemq.artemis.api.core.ActiveMQSecurityException: AMQ229031: Unable to validate user from /10.11.1.3:62895. Username: null; SSL certificate subject DN: unavailable
        at org.apache.activemq.artemis.core.security.impl.SecurityStoreImpl.authenticationFailed(SecurityStoreImpl.java:360) ~[artemis-server-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.core.security.impl.SecurityStoreImpl.authenticate(SecurityStoreImpl.java:189) ~[artemis-server-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl.validateUser(ActiveMQServerImpl.java:1744) ~[artemis-server-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl.createSession(ActiveMQServerImpl.java:1724) ~[artemis-server-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.broker.AMQPSessionCallback.init(AMQPSessionCallback.java:207) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.AMQPSessionContext.initialize(AMQPSessionContext.java:86) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.AMQPConnectionContext.onRemoteOpen(AMQPConnectionContext.java:691) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.handler.Events.dispatch(Events.java:50) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler.dispatch(ProtonHandler.java:565) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler.flush(ProtonHandler.java:361) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler.inputBuffer(ProtonHandler.java:318) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.AMQPConnectionContext.inputBuffer(AMQPConnectionContext.java:242) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.broker.ActiveMQProtonRemotingConnection.bufferReceived(ActiveMQProtonRemotingConnection.java:134) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.core.remoting.server.impl.RemotingServiceImpl$DelegatingBufferHandler.bufferReceived(RemotingServiceImpl.java:691) ~[artemis-server-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.core.remoting.impl.netty.ActiveMQChannelHandler.channelRead(ActiveMQChannelHandler.java:73) ~[artemis-core-client-2.27.1.jar:2.27.1]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:800) ~[netty-transport-classes-epoll-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:499) ~[netty-transport-classes-epoll-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:397) ~[netty-transport-classes-epoll-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.82.Final.jar:4.1.82.Final]
        at org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run(ActiveMQThreadFactory.java:118) ~[artemis-commons-2.27.1.jar:?]
2023-01-15 12:46:35,849 WARN  [org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler] null
java.lang.NullPointerException: null
        at org.apache.activemq.artemis.protocol.amqp.broker.AMQPSessionCallback.getAddress(AMQPSessionCallback.java:724) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.ProtonServerReceiverContext.getRoutingType(ProtonServerReceiverContext.java:169) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.ProtonServerReceiverContext.initialize(ProtonServerReceiverContext.java:119) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.AMQPSessionContext.addReceiver(AMQPSessionContext.java:256) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.AMQPConnectionContext.remoteLinkOpened(AMQPConnectionContext.java:391) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.AMQPConnectionContext.onRemoteOpen(AMQPConnectionContext.java:712) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.handler.Events.dispatch(Events.java:68) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler.dispatch(ProtonHandler.java:565) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler.flush(ProtonHandler.java:361) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.handler.ProtonHandler.inputBuffer(ProtonHandler.java:318) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.proton.AMQPConnectionContext.inputBuffer(AMQPConnectionContext.java:242) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.protocol.amqp.broker.ActiveMQProtonRemotingConnection.bufferReceived(ActiveMQProtonRemotingConnection.java:134) ~[artemis-amqp-protocol-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.core.remoting.server.impl.RemotingServiceImpl$DelegatingBufferHandler.bufferReceived(RemotingServiceImpl.java:691) ~[artemis-server-2.27.1.jar:2.27.1]
        at org.apache.activemq.artemis.core.remoting.impl.netty.ActiveMQChannelHandler.channelRead(ActiveMQChannelHandler.java:73) ~[artemis-core-client-2.27.1.jar:2.27.1]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) ~[netty-transport-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:800) ~[netty-transport-classes-epoll-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:499) ~[netty-transport-classes-epoll-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:397) ~[netty-transport-classes-epoll-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.82.Final.jar:4.1.82.Final]
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.82.Final.jar:4.1.82.Final]
        at org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run(ActiveMQThreadFactory.java:118) ~[artemis-commons-2.27.1.jar:?]

Issue Links

• links to: GitHub Pull Request #4339