Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Bug] Fix handle http message throw IllegalReferenceCountException #3271

Closed
2 tasks done
mxsm opened this issue Feb 26, 2023 · 7 comments · Fixed by #3272
Closed
2 tasks done

[Bug] Fix handle http message throw IllegalReferenceCountException #3271

mxsm opened this issue Feb 26, 2023 · 7 comments · Fixed by #3272
Labels
bug Something isn't working
Milestone

Comments

@mxsm
Copy link
Member

mxsm commented Feb 26, 2023

Search before asking

  • I had searched in the issues and found no similar issues.

Environment

Windows

EventMesh version

master

What happened

When I send http message to server. Causes the following problems:
image

How to reproduce

Sending messages over http

public class HTTP {
    public static void main(String[] args) throws Exception {
        EventMeshHttpClientConfig eventMeshClientConfig = EventMeshHttpClientConfig.builder()
            .liteEventMeshAddr("192.168.1.7:10105")
            .producerGroup("TEST_PRODUCER_GROUP")
            .env("DEV")
            .idc("idc")
            .ip(IPUtils.getLocalAddress())
            .sys("1234")
            .pid(String.valueOf(ThreadUtils.getPID()))
            .userName("eventmesh")
            .password("password")
            .build();
        /* ... */
        EventMeshHttpProducer eventMeshHttpProducer = new EventMeshHttpProducer(eventMeshClientConfig);
        Map<String, String> content = new HashMap<>();
        content.put("content", "testAsyncMessage");

        CloudEvent event = CloudEventBuilder.v1()
            .withId(UUID.randomUUID().toString())
            .withSubject("eventmesh-async-topic")
            .withSource(URI.create("/"))
            .withDataContentType("application/cloudevents+json")
            .withType(EventMeshCommon.CLOUD_EVENTS_PROTOCOL_NAME)
            .withData(JsonUtils.toJSONString(content).getBytes(StandardCharsets.UTF_8))
            .withExtension(Constants.EVENTMESH_MESSAGE_CONST_TTL, String.valueOf(4 * 1000))
            .build();
        eventMeshHttpProducer.publish(event);
    }
}

Debug logs

2023-02-26 09:22:28,703 ERROR [eventMesh-http-worker-1] AbstractHTTPServer(AbstractHTTPServer.java:595) - 
io.netty.util.IllegalReferenceCountException: refCnt: 0, decrement: 1
	at io.netty.util.internal.ReferenceCountUpdater.toLiveRealRefCnt(ReferenceCountUpdater.java:83) ~[netty-common-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.util.internal.ReferenceCountUpdater.release(ReferenceCountUpdater.java:147) ~[netty-common-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.buffer.AbstractReferenceCountedByteBuf.release(AbstractReferenceCountedByteBuf.java:101) ~[netty-buffer-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.handler.codec.http.HttpObjectAggregator$AggregatedFullHttpMessage.release(HttpObjectAggregator.java:378) ~[netty-codec-http-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.util.ReferenceCountUtil.release(ReferenceCountUtil.java:90) ~[netty-common-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:106) ~[netty-transport-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103) [netty-codec-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:327) [netty-codec-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:299) [netty-codec-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.channel.AbstractChannelHandlerContext.access$600(AbstractChannelHandlerContext.java:61) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.channel.AbstractChannelHandlerContext$7.run(AbstractChannelHandlerContext.java:370) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.util.concurrent.AbstractEventExecutor.runTask$$$capture(AbstractEventExecutor.java:174) [netty-common-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java) [netty-common-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute$$$capture(AbstractEventExecutor.java:167) [netty-common-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java) [netty-common-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470) [netty-common-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:503) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) [netty-common-4.1.79.Final.jar:4.1.79.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-common-4.1.79.Final.jar:4.1.79.Final]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_202]
2023-02-26 09:22:28,703 INFO  [eventMesh-sendMsg-1] cmd(SendAsyncMessageProcessor.java:89) - cmd=MSG_SEND_ASYNC|http|client2eventMesh|from=192.168.1.7:52094|to=192.168.43.1

Are you willing to submit PR?

  • Yes I am willing to submit a PR!
@mxsm mxsm added the bug Something isn't working label Feb 26, 2023
@mxsm mxsm changed the title [Bug] Fix [Bug] Fix handle http message throw IllegalReferenceCountException Feb 26, 2023
mxsm added a commit to mxsm/incubator-eventmesh that referenced this issue Feb 26, 2023
@jonyangx
Copy link
Contributor

@mxsm pls add full error log.

@mxsm
Copy link
Member Author

mxsm commented Feb 27, 2023

@mxsm pls add full error log.

@jonyangx This is the complete error log

@mxsm
Copy link
Member Author

mxsm commented Feb 27, 2023

@jonyangx Now HTTPHandler extends SimpleChannelInboundHandler, but when channelRead0 finished code invoked ReferenceCountUtil.release method.
image
However in SimpleChannelInboundHandler class do the same thing:
image

ReferenceCountUtil.release twice, So throw the exception in the log above.

I hava described in pr.

@jonyangx
Copy link
Contributor

I couldn't reproduced the scene, and test is success. @mxsm

@mxsm
Copy link
Member Author

mxsm commented Feb 27, 2023

I couldn't reproduced the scene, and test is success. @mxsm

@jonyangx make sure you HTTPHandler extends SimpleChannelInboundHandler, I refactor it before. Also because the refactoring I ignored the code that executes the ReferenceCountUtil release method
pull the latest code from master. start runtime and use this test code:

public class HTTP {
    public static void main(String[] args) throws Exception {
        EventMeshHttpClientConfig eventMeshClientConfig = EventMeshHttpClientConfig.builder()
            .liteEventMeshAddr("192.168.1.7:10105")
            .producerGroup("TEST_PRODUCER_GROUP")
            .env("DEV")
            .idc("idc")
            .ip(IPUtils.getLocalAddress())
            .sys("1234")
            .pid(String.valueOf(ThreadUtils.getPID()))
            .userName("eventmesh")
            .password("password")
            .build();
        /* ... */
        EventMeshHttpProducer eventMeshHttpProducer = new EventMeshHttpProducer(eventMeshClientConfig);
        Map<String, String> content = new HashMap<>();
        content.put("content", "testAsyncMessage");

        CloudEvent event = CloudEventBuilder.v1()
            .withId(UUID.randomUUID().toString())
            .withSubject("eventmesh-async-topic")
            .withSource(URI.create("/"))
            .withDataContentType("application/cloudevents+json")
            .withType(EventMeshCommon.CLOUD_EVENTS_PROTOCOL_NAME)
            .withData(JsonUtils.toJSONString(content).getBytes(StandardCharsets.UTF_8))
            .withExtension(Constants.EVENTMESH_MESSAGE_CONST_TTL, String.valueOf(4 * 1000))
            .build();
        eventMeshHttpProducer.publish(event);
    }
}

@jonyangx
Copy link
Contributor

jonyangx commented Feb 27, 2023

@mxsm I start eventmesh http server using org.apache.eventmesh.runtime.boot.EventMeshStartup, and use HTTP class as client .
Test code is success,server has no error log.
2023-02-27 12:13:04,539 main DEBUG Apache Log4j Core 2.17.1 initializing configuration XmlConfiguration[location=/Users/apple/opensource/incubator-eventmesh/eventmesh-sdk-java/build/resources/test/log4j2.xml]
2023-02-27 12:13:04,544 main DEBUG Installed 1 script engine
2023-02-27 12:13:04,707 main DEBUG Oracle Nashorn version: 1.8.0_271, language: ECMAScript, threading: Not Thread Safe, compile: true, names: [nashorn, Nashorn, js, JS, JavaScript, javascript, ECMAScript, ecmascript], factory class: jdk.nashorn.api.scripting.NashornScriptEngineFactory
2023-02-27 12:13:04,708 main DEBUG PluginManager 'Core' found 127 plugins
2023-02-27 12:13:04,708 main DEBUG PluginManager 'Level' found 0 plugins
2023-02-27 12:13:04,710 main DEBUG PluginManager 'Lookup' found 16 plugins
2023-02-27 12:13:04,711 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout].
2023-02-27 12:13:04,719 main DEBUG PluginManager 'TypeConverter' found 26 plugins
2023-02-27 12:13:04,728 main DEBUG PatternLayout$Builder(pattern="%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p [%t] %c{1}(%F:%L) - %m%n", PatternSelector=null, Configuration(/Users/apple/opensource/incubator-eventmesh/eventmesh-sdk-java/build/resources/test/log4j2.xml), Replace=null, charset="null", alwaysWriteExceptions="null", disableAnsi="null", noConsoleNoAnsi="null", header="null", footer="null")
2023-02-27 12:13:04,728 main DEBUG PluginManager 'Converter' found 45 plugins
2023-02-27 12:13:04,736 main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.ConsoleAppender].
2023-02-27 12:13:04,741 main DEBUG ConsoleAppender$Builder(target="SYSTEM_OUT", follow="null", direct="null", bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p [%t] %c{1}(%F:%L) - %m%n), name="console", Configuration(/Users/apple/opensource/incubator-eventmesh/eventmesh-sdk-java/build/resources/test/log4j2.xml), Filter=null, ={})
2023-02-27 12:13:04,742 main DEBUG Starting OutputStreamManager SYSTEM_OUT.false.false
2023-02-27 12:13:04,743 main DEBUG Building Plugin[name=appenders, class=org.apache.logging.log4j.core.config.AppendersPlugin].
2023-02-27 12:13:04,743 main DEBUG createAppenders(={console})
2023-02-27 12:13:04,743 main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
2023-02-27 12:13:04,746 main DEBUG createAppenderRef(ref="console", level="null", Filter=null)
2023-02-27 12:13:04,746 main DEBUG Building Plugin[name=asyncRoot, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig$RootLogger].
2023-02-27 12:13:04,747 main DEBUG createLogger(additivity="null", level="DEBUG", includeLocation="true", ={console}, ={}, Configuration(/Users/apple/opensource/incubator-eventmesh/eventmesh-sdk-java/build/resources/test/log4j2.xml), Filter=null)
2023-02-27 12:13:04,751 main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
2023-02-27 12:13:04,752 main DEBUG createAppenderRef(ref="console", level="null", Filter=null)
2023-02-27 12:13:04,753 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2023-02-27 12:13:04,754 main DEBUG createLogger(additivity="false", level="DEBUG", name="org.apache.eventmesh.client", includeLocation="true", ={console}, ={}, Configuration(/Users/apple/opensource/incubator-eventmesh/eventmesh-sdk-java/build/resources/test/log4j2.xml), Filter=null)
2023-02-27 12:13:04,754 main DEBUG Building Plugin[name=loggers, class=org.apache.logging.log4j.core.config.LoggersPlugin].
2023-02-27 12:13:04,754 main DEBUG createLoggers(={root, org.apache.eventmesh.client})
2023-02-27 12:13:04,755 main DEBUG Configuration XmlConfiguration[location=/Users/apple/opensource/incubator-eventmesh/eventmesh-sdk-java/build/resources/test/log4j2.xml] initialized
2023-02-27 12:13:04,755 main DEBUG Starting configuration XmlConfiguration[location=/Users/apple/opensource/incubator-eventmesh/eventmesh-sdk-java/build/resources/test/log4j2.xml]
2023-02-27 12:13:04,756 main DEBUG Log4j2 ConfigurationScheduler starting 1 threads
2023-02-27 12:13:04,770 main DEBUG Starting AsyncLoggerConfig disruptor for this configuration with ringbufferSize=4096, waitStrategy=TimeoutBlockingWaitStrategy, exceptionHandler=org.apache.logging.log4j.core.async.AsyncLoggerConfigDefaultExceptionHandler@503d687a...
2023-02-27 12:13:04,770 main DEBUG Started configuration XmlConfiguration[location=/Users/apple/opensource/incubator-eventmesh/eventmesh-sdk-java/build/resources/test/log4j2.xml] OK.
2023-02-27 12:13:04,770 main DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false-1
2023-02-27 12:13:04,771 main DEBUG OutputStream closed
2023-02-27 12:13:04,771 main DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false-1, all resources released: true
2023-02-27 12:13:04,771 main DEBUG Appender DefaultConsole-1 stopped with status true
2023-02-27 12:13:04,771 main DEBUG Stopped org.apache.logging.log4j.core.config.DefaultConfiguration@6a5fc7f7 OK
2023-02-27 12:13:04,805 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93
2023-02-27 12:13:04,808 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=StatusLogger
2023-02-27 12:13:04,809 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=ContextSelector
2023-02-27 12:13:04,810 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=Loggers,name=
2023-02-27 12:13:04,810 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=Loggers,name=,subtype=RingBuffer
2023-02-27 12:13:04,810 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=Loggers,name=org.apache.eventmesh.client
2023-02-27 12:13:04,811 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=Loggers,name=org.apache.eventmesh.client,subtype=RingBuffer
2023-02-27 12:13:04,811 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=Appenders,name=console
2023-02-27 12:13:04,813 main DEBUG org.apache.logging.log4j.core.util.SystemClock does not support precise timestamps.
2023-02-27 12:13:04,814 main DEBUG Reconfiguration complete for context[name=73d16e93] at URI /Users/apple/opensource/incubator-eventmesh/eventmesh-sdk-java/build/resources/test/log4j2.xml (org.apache.logging.log4j.core.LoggerContext@73700b80) with optional ClassLoader: null
2023-02-27 12:13:04,814 main DEBUG Shutdown hook enabled. Registering a new one.
2023-02-27 12:13:04,814 main DEBUG LoggerContext[name=73d16e93, org.apache.logging.log4j.core.LoggerContext@73700b80] started OK.
2023-02-27 12:13:05,233 DEBUG [main] InternalLoggerFactory(InternalLoggerFactory.java:63) - Using SLF4J as the default logging framework
2023-02-27 12:13:05,237 DEBUG [main] PlatformDependent0(PlatformDependent0.java:495) - -Dio.netty.noUnsafe: false
2023-02-27 12:13:05,237 DEBUG [main] PlatformDependent0(PlatformDependent0.java:998) - Java version: 8
2023-02-27 12:13:05,238 DEBUG [main] PlatformDependent0(PlatformDependent0.java:136) - sun.misc.Unsafe.theUnsafe: available
2023-02-27 12:13:05,238 DEBUG [main] PlatformDependent0(PlatformDependent0.java:160) - sun.misc.Unsafe.copyMemory: available
2023-02-27 12:13:05,238 DEBUG [main] PlatformDependent0(PlatformDependent0.java:192) - sun.misc.Unsafe.storeFence: available
2023-02-27 12:13:05,239 DEBUG [main] PlatformDependent0(PlatformDependent0.java:235) - java.nio.Buffer.address: available
2023-02-27 12:13:05,239 DEBUG [main] PlatformDependent0(PlatformDependent0.java:306) - direct buffer constructor: available
2023-02-27 12:13:05,240 DEBUG [main] PlatformDependent0(PlatformDependent0.java:384) - java.nio.Bits.unaligned: available, true
2023-02-27 12:13:05,240 DEBUG [main] PlatformDependent0(PlatformDependent0.java:458) - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable prior to Java9
2023-02-27 12:13:05,240 DEBUG [main] PlatformDependent0(PlatformDependent0.java:481) - java.nio.DirectByteBuffer.(long, int): available
2023-02-27 12:13:05,240 DEBUG [main] PlatformDependent(PlatformDependent.java:1159) - sun.misc.Unsafe: available
2023-02-27 12:13:05,240 DEBUG [main] PlatformDependent(PlatformDependent.java:1289) - -Dio.netty.tmpdir: /var/folders/12/dc96p6f11pg6ldnjp100dkch0000gp/T (java.io.tmpdir)
2023-02-27 12:13:05,240 DEBUG [main] PlatformDependent(PlatformDependent.java:1368) - -Dio.netty.bitMode: 64 (sun.arch.data.model)
2023-02-27 12:13:05,241 DEBUG [main] PlatformDependent(PlatformDependent.java:1127) - Platform: MacOS
2023-02-27 12:13:05,241 DEBUG [main] PlatformDependent(PlatformDependent.java:178) - -Dio.netty.maxDirectMemory: 7635730432 bytes
2023-02-27 12:13:05,241 DEBUG [main] PlatformDependent(PlatformDependent.java:185) - -Dio.netty.uninitializedArrayAllocationThreshold: -1
2023-02-27 12:13:05,242 DEBUG [main] CleanerJava6(CleanerJava6.java:92) - java.nio.ByteBuffer.cleaner(): available
2023-02-27 12:13:05,242 DEBUG [main] PlatformDependent(PlatformDependent.java:205) - -Dio.netty.noPreferDirect: false
2023-02-27 12:13:05,259 DEBUG [main] HttpUtils(HttpUtils.java:144) - POST http://127.0.0.1:10105 HTTP/1.1
2023-02-27 12:13:05,554 DEBUG [main] HttpUtils(HttpUtils.java:63) - HttpUtils.ResponseHolder(response={"retCode":0,"retMsg":"successSendResult[topic=eventmesh-async-topic, messageId=0]","resTime":1677471185513})
2023-02-27 12:13:05,585 pool-1-thread-1 DEBUG Stopping LoggerContext[name=73d16e93, org.apache.logging.log4j.core.LoggerContext@73700b80]
2023-02-27 12:13:05,585 pool-1-thread-1 DEBUG Stopping LoggerContext[name=73d16e93, org.apache.logging.log4j.core.LoggerContext@73700b80]...
2023-02-27 12:13:05,587 pool-1-thread-1 DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false
2023-02-27 12:13:05,587 pool-1-thread-1 DEBUG OutputStream closed
2023-02-27 12:13:05,587 pool-1-thread-1 DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false, all resources released: true
2023-02-27 12:13:05,588 pool-1-thread-1 DEBUG Appender console stopped with status true
2023-02-27 12:13:05,588 pool-1-thread-1 DEBUG Log4j2 ConfigurationScheduler shutting down threads in java.util.concurrent.ScheduledThreadPoolExecutor@34294cbf[Running, pool size = 1, active threads = 0, queued tasks = 1, completed tasks = 0]
2023-02-27 12:13:05,588 pool-1-thread-1 DEBUG Stopped XmlConfiguration[location=/Users/apple/opensource/incubator-eventmesh/eventmesh-sdk-java/build/resources/test/log4j2.xml] OK
2023-02-27 12:13:05,588 pool-1-thread-1 DEBUG Stopped LoggerContext[name=73d16e93, org.apache.logging.log4j.core.LoggerContext@73700b80] with status true

BUILD SUCCESSFUL in 11s

@mxsm
Copy link
Member Author

mxsm commented Feb 27, 2023

@jonyangx
started in IDEA, master and the latest code:
image
test code :
image
then run test code, runtime server exception:

2023-02-27 15:36:32,016 DEBUG [eventMesh-http-worker-2] AbstractHTTPServer(AbstractHTTPServer.java:438) - httpCommand={REQ,POST/HTTP,requestCode=104,opaque=3,header=sendMessageRequestHeader={code=104,language=JAVA,version=V1,env=DEV,idc=idc,sys=1234,pid=21436,ip=172.19.63.136:57237,username=eventmesh,passwd=password},body=sendMessageRequestBody={topic=null,bizSeqNo=null,uniqueId=null,content={"specversion":"1.0","id":"a1e291f2-8efa-4a40-9566-0fbcd0715a44","source":"/","type":"cloudevents","datacontenttype":"application/cloudevents+json","subject":"eventmesh-async-topic","protocolversion":"1.0","ip":"172.19.63.136","idc":"idc","protocoldesc":"V1","bizseqno":"750847729482426165841644938330","pid":"21436","language":"JAVA","env":"DEV","sys":"1234","ttl":"4000","uniqueid":"283198725850969120046106290900","data_base64":"eyJjb250ZW50IjoidGVzdEFzeW5jTWVzc2FnZSJ9"},ttl=null,tag=,producerGroup=TEST_PRODUCER_GROUP,extFields=null}}
2023-02-27 15:36:32,017 ERROR [eventMesh-http-worker-2] AbstractHTTPServer(AbstractHTTPServer.java:595) - 
io.netty.util.IllegalReferenceCountException: refCnt: 0, decrement: 1
   at io.netty.util.internal.ReferenceCountUpdater.toLiveRealRefCnt(ReferenceCountUpdater.java:83) ~[netty-common-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.util.internal.ReferenceCountUpdater.release(ReferenceCountUpdater.java:147) ~[netty-common-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.buffer.AbstractReferenceCountedByteBuf.release(AbstractReferenceCountedByteBuf.java:101) ~[netty-buffer-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.handler.codec.http.HttpObjectAggregator$AggregatedFullHttpMessage.release(HttpObjectAggregator.java:378) ~[netty-codec-http-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.util.ReferenceCountUtil.release(ReferenceCountUtil.java:90) ~[netty-common-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:106) ~[netty-transport-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103) [netty-codec-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:327) [netty-codec-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:299) [netty-codec-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.channel.AbstractChannelHandlerContext.access$600(AbstractChannelHandlerContext.java:61) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.channel.AbstractChannelHandlerContext$7.run(AbstractChannelHandlerContext.java:370) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.util.concurrent.AbstractEventExecutor.runTask$$$capture(AbstractEventExecutor.java:174) [netty-common-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java) [netty-common-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.util.concurrent.AbstractEventExecutor.safeExecute$$$capture(AbstractEventExecutor.java:167) [netty-common-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java) [netty-common-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470) [netty-common-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:503) [netty-transport-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) [netty-common-4.1.79.Final.jar:4.1.79.Final]
   at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-common-4.1.79.Final.jar:4.1.79.Final]
   at java.lang.Thread.run(Thread.java:748) [?:1.8.0_202]
2023-02-27 15:36:32,373 INFO  [eventMesh-sendMsg-2] cmd(SendAsyncMessageProcessor.java:89) - cmd=MSG_SEND_ASYNC|http|client2eventMesh|from=172.19.63.136:57237|to=172.19.63.136
2023-02-27 15:36:32,374 DEBUG [eventMesh-sendMsg-2] message(SendAsyncMessageProcessor.java:262) - msg2MQMsg suc, bizSeqNo=750847729482426165841644938330, topic=eventmesh-async-topic
2023-02-27 15:36:32,374 INFO  [eventMesh-sendMsg-2] message(SendAsyncMessageProcessor.java:319) - message|eventMesh2mq|REQ|ASYNC|send2MQCost=0ms|topic=eventmesh-async-topic|bizSeqNo=750847729482426165841644938330|uniqueId=283198725850969120046106290900
2023-02-27 15:36:32,374 DEBUG [eventMesh-sendMsg-2] TraceUtils(TraceUtils.java:86) - finishSpan with event:CloudEvent{id='a1e291f2-8efa-4a40-9566-0fbcd0715a44', source=/, type='cloudevents', datacontenttype='application/cloudevents+json', subject='eventmesh-async-topic', data=BytesCloudEventData{value=[123, 34, 99, 111, 110, 116, 101, 110, 116, 34, 58, 34, 116, 101, 115, 116, 65, 115, 121, 110, 99, 77, 101, 115, 115, 97, 103, 101, 34, 125]}, extensions={protocolversion=1.0, reqeventmesh2mqtimestamp=1677483392374, code=104, reqsendeventmeship=172.19.63.136, ip=172.19.63.136:57237, idc=idc, protocoldesc=http, pid=21436, language=JAVA, env=DEV, sys=1234, ttl=4000, version=1.0, producergroup=TEST_PRODUCER_GROUP, passwd=password, bizseqno=750847729482426165841644938330, protocoltype=cloudevents, msgtype=persistent, uniqueid=283198725850969120046106290900, username=eventmesh, reqc2eventmeshtimestamp=1677483392015}}
2023-02-27 15:36:32,374 DEBUG [eventMesh-sendMsg-2] TraceUtils(TraceUtils.java:86) - finishSpan with event:CloudEvent{id='a1e291f2-8efa-4a40-9566-0fbcd0715a44', source=/, type='cloudevents', datacontenttype='application/cloudevents+json', subject='eventmesh-async-topic', data=BytesCloudEventData{value=[123, 34, 99, 111, 110, 116, 101, 110, 116, 34, 58, 34, 116, 101, 115, 116, 65, 115, 121, 110, 99, 77, 101, 115, 115, 97, 103, 101, 34, 125]}, extensions={protocolversion=1.0, reqeventmesh2mqtimestamp=1677483392374, code=104, reqsendeventmeship=172.19.63.136, ip=172.19.63.136:57237, idc=idc, protocoldesc=http, pid=21436, language=JAVA, env=DEV, sys=1234, ttl=4000, version=1.0, producergroup=TEST_PRODUCER_GROUP, passwd=password, bizseqno=750847729482426165841644938330, protocoltype=cloudevents, msgtype=persistent, uniqueid=283198725850969120046106290900, username=eventmesh, reqc2eventmeshtimestamp=1677483392015}}
2023-02-27 15:36:32,374 DEBUG [eventMesh-sendMsg-2] AbstractHTTPServer(AbstractHTTPServer.java:555) - httpCommand={RES,POST/HTTP,requestCode=104,opaque=3,cost=359,header=sendMessageResponseHeader={code=104,eventMeshEnv=PRD,eventMeshIdc=DEFAULT,eventMeshCluster=COMMON,eventMeshIp=172.19.63.136},body=sendMessageResponseBody={retCode=0,retMsg=successSendResult[topic=eventmesh-async-topic, messageId=1],resTime=2023-02-27 15:36:32.374}}
2023-02-27 15:36:32,374 DEBUG [EventMesh-http-asyncContext-2] http(SendAsyncMessageProcessor.java:288) - httpCommand={RES,POST/HTTP,requestCode=104,opaque=3,cost=359,header=sendMessageResponseHeader={code=104,eventMeshEnv=PRD,eventMeshIdc=DEFAULT,eventMeshCluster=COMMON,eventMeshIp=172.19.63.136},body=sendMessageResponseBody={retCode=0,retMsg=successSendResult[topic=eventmesh-async-topic, messageId=1],resTime=2023-02-27 15:36:32.374}}
2023-02-27 15:36:32,376 WARN  [eventMesh-http-worker-2] AbstractHTTPServer(AbstractHTTPServer.java:194) - send response to [172.19.63.136:57237] fail, will close this channel
2023-02-27 15:36:32,376 WARN  [eventMesh-http-worker-2] AbstractHTTPServer(AbstractHTTPServer.java:194) - send response to [172.19.63.136:57237] fail, will close this channel

xwm1992 added a commit that referenced this issue Feb 27, 2023
[ISSUE #3271]Fix handle http message throw IllegalReferenceCountException
mytang0 added a commit to mytang0/eventmesh that referenced this issue Feb 27, 2023
@xwm1992 xwm1992 added this to the 1.9.0 milestone Jun 27, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants