Fix re-transform bug when enhanced class proxy parent method #659

kylixs · 2023-12-16T10:28:42Z

Fix re-transform bug when enhanced class proxy parent method

For example, re-transform Jedis failed with Arthas : apache/skywalking#11651

Add a unit test to verify that the fix works.
Explain briefly why the bug exists and how to fix it.

What happened

Run app with Java Agent 9.1.0, watching redis.clients.jedis.Jedis withArthas reported:

java.lang.UnsupportedOperationException: class redefinition failed: attempted to change the schema (add/remove fields)

The JDK17 log (Xlog) display an error:

[40.198s][info][redefine,class,normalize] redefined class redis.clients.jedis.Jedis fields change error: field Ljava/lang/reflect/Method; cachedValue$$sw$v9vk4i1$rc1vrg3 changed to Ljava/lang/reflect/Method; cachedValue$$sw$v9vk4i1$kq3fl10.

Open redefine log by:

java -Xlog:redefine*=info -javaagent:/path/skywalking-agent.jar  -jar  app.jar

Analyze with javap -p and compare the bytecode before and after retransform, it is found that the field name of the proxy method changes.
Found the number of declaration methods returned during retransform is increased and not in the same order. The extra methods comes from the parent class, and the methods are evaluated in a different order each time.
For example, the method get(byte[]) of redis.clients.jedis.BinaryJedis will be added to redis.clients.jedis.Jedis after jedis plugin is enhanced.

How to fix it

SWDescriptionStrategy: Return original methods in the same order, removing generated methods for delegating superclass calls and others.
SWMethodGraphCompilerDelegate: Sort methods of MethodGraph compute from the parent classes.

If this pull request closes/resolves/fixes an existing issue, replace the issue number. Closes #.
Update the CHANGES log.

wu-sheng · 2023-12-16T11:29:15Z

I think this is a general change, rather than fixing Jedis, right?

kylixs · 2023-12-16T12:08:49Z

I think this is a general change, rather than fixing Jedis, right?

Yes, any class that enhances a method from a parent class will have a similar error.

kylixs · 2023-12-16T12:12:03Z

I want to create an abstract test class that makes it easy to test re-transform in a plug-in module, such as JedisInstrumentationTest. Because of using SkyWalkingAgent#installClassTransformer() method in apm-agent, it can not put in bytebuddy-patch module, a bit painful, any suggestions?

wu-sheng · 2023-12-16T13:08:35Z

I want to create an abstract test class that makes it easy to test re-transform in a plug-in module, such as JedisInstrumentationTest. Because of using SkyWalkingAgent#installClassTransformer() method in apm-agent, it can not put in bytebuddy-patch module, a bit painful, any suggestions?

Does this indicate, you are actually testing agent, rather than patch?

kylixs · 2023-12-16T13:27:51Z

Does this indicate, you are actually testing agent, rather than patch?

Actually, test re-transforming of plugin

wu-sheng · 2023-12-16T13:30:29Z

Yes, then this is a test scenario, I think you could write a plugin test to verify this. It doesn't matter it is about bytebuddy patch or not.

kylixs · 2023-12-16T13:44:37Z

Write a plugin test to test all plugin maybe difficult, it need to load many classes and some of them are conflicted.

wu-sheng · 2023-12-16T13:47:38Z

Write a plugin test to test all plugin maybe difficult, it need to load many classes and some of them are conflicted.

Then how do you prefer to test this? If there isn't a real agent running.

kylixs · 2023-12-16T14:08:45Z

Then how do you prefer to test this? If there isn't a real agent running.

I found it does not need to test in real agent, it just need test by re-transform the enhanced class after plugin enhance. Check about JedisInstrumentationTest.

wu-sheng · 2023-12-16T15:44:45Z

I did a quick read on JedisInstrumentationTest. Generally, you could write mock classes in the agent repository, and redo the UTs, right? It doesn't need to be inside Jedis plugin.

xzyJavaX · 2023-12-19T02:22:34Z

@kylixs It seems that Jedis is fine, but there will still be a TypeNotPresentException with watch org.apache.kafka.clients/product.KafkaProducer send - x 1

lujiajing1126 · 2023-12-19T02:28:00Z

I did a quick read on JedisInstrumentationTest. Generally, you could write mock classes in the agent repository, and redo the UTs, right? It doesn't need to be inside Jedis plugin.

I agree that we should introduce some-how "general" way to test the re-transform mechanism like our E2E for plugins.

kylixs · 2023-12-19T04:00:23Z

@kylixs It seems that Jedis is fine, but there will still be a TypeNotPresentException with watch org.apache.kafka.clients/product.KafkaProducer send - x 1

@xyyz150 It works correctly in windows11 + jdk 17. Your environment? Error details?

xzyJavaX · 2023-12-19T05:55:50Z

mac+jdk17.Error details:
Affect(class count: 0 , method count: 2) cost in 163 ms, listenerId: 1 Enhance error! exception: java.lang.TypeNotPresentException: Type org/apache/kafka/clients/producer/KafkaProducer$$sw$auxiliary$mhh2bd0 not present error happens when enhancing class: Type org/apache/kafka/clients/producer/KafkaProducer$$sw$auxiliary$mhh2bd0 not present, check arthas log: /Users/xzy/logs/arthas/arthas.log

wu-sheng · 2023-12-20T14:30:20Z

@kylixs @xzyJavaX What is the update here? Are we facing inconsistent test results now?

kylixs · 2023-12-22T02:18:25Z

mac+jdk17.Error details: Affect(class count: 0 , method count: 2) cost in 163 ms, listenerId: 1 Enhance error! exception: java.lang.TypeNotPresentException: Type org/apache/kafka/clients/producer/KafkaProducer$$sw$auxiliary$mhh2bd0 not present error happens when enhancing class: Type org/apache/kafka/clients/producer/KafkaProducer$$sw$auxiliary$mhh2bd0 not present, check arthas log: /Users/xzy/logs/arthas/arthas.log

Please check error details in file: ${user home}/logs/arthas.log
More details? CPU arch? OS and Java version?

lujiajing1126 · 2023-12-22T03:36:13Z

mac+jdk17.Error details: Affect(class count: 0 , method count: 2) cost in 163 ms, listenerId: 1 Enhance error! exception: java.lang.TypeNotPresentException: Type org/apache/kafka/clients/producer/KafkaProducer$$sw$auxiliary$mhh2bd0 not present error happens when enhancing class: Type org/apache/kafka/clients/producer/KafkaProducer$$sw$auxiliary$mhh2bd0 not present, check arthas log: /Users/xzy/logs/arthas/arthas.log

Please check error details in file: ${user home}/logs/arthas.log More details? CPU arch? OS and Java version?

I've confirmed that Kafka issue still exists while Redis issue has been resolved.

OS: macOS sonoma
Arch: aarch64
Java: zulu 17.46.19

Error logs shown in arthas.log,

2023-12-22 11:32:55 [arthas-command-execute] INFO  c.t.arthas.core.advisor.Enhancer -enhance matched classes: [class org.apache.kafka.clients.producer.KafkaProducer]
2023-12-22 11:32:55 [arthas-command-execute] WARN  c.t.arthas.core.advisor.Enhancer -transform loader[org.springframework.boot.loader.LaunchedURLClassLoader@8c46918]:class[org/apache/kafka/clients/producer/KafkaProducer] failed.
java.lang.TypeNotPresentException: Type org/apache/kafka/clients/producer/KafkaProducer$$sw$auxiliary$o9jqgj1 not present
	at com.alibaba.deps.org.objectweb.asm.ClassWriter.getCommonSuperClass(ClassWriter.java:1051)
	at com.alibaba.bytekit.asm.ClassMetaClassWriter.getCommonSuperClass(ClassMetaClassWriter.java:43)
	at com.alibaba.deps.org.objectweb.asm.SymbolTable.addMergedType(SymbolTable.java:1202)
	at com.alibaba.deps.org.objectweb.asm.Frame.merge(Frame.java:1300)
	at com.alibaba.deps.org.objectweb.asm.Frame.merge(Frame.java:1198)
	at com.alibaba.deps.org.objectweb.asm.MethodWriter.computeAllFrames(MethodWriter.java:1611)
	at com.alibaba.deps.org.objectweb.asm.MethodWriter.visitMaxs(MethodWriter.java:1547)
	at com.alibaba.deps.org.objectweb.asm.tree.MethodNode.accept(MethodNode.java:767)
	at com.alibaba.deps.org.objectweb.asm.tree.MethodNode.accept(MethodNode.java:647)
	at com.alibaba.deps.org.objectweb.asm.tree.ClassNode.accept(ClassNode.java:468)
	at com.alibaba.bytekit.utils.AsmUtils.toBytes(AsmUtils.java:80)
	at com.taobao.arthas.core.advisor.Enhancer.transform(Enhancer.java:256)
	at com.taobao.arthas.core.advisor.TransformerManager$1.transform(TransformerManager.java:51)
	at java.instrument/java.lang.instrument.ClassFileTransformer.transform(ClassFileTransformer.java:244)
	at java.instrument/sun.instrument.TransformerManager.transform(TransformerManager.java:188)
	at java.instrument/sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:541)
	at java.instrument/sun.instrument.InstrumentationImpl.retransformClasses0(Native Method)
	at java.instrument/sun.instrument.InstrumentationImpl.retransformClasses(InstrumentationImpl.java:169)
	at com.taobao.arthas.core.advisor.Enhancer.enhance(Enhancer.java:446)
	at com.taobao.arthas.core.command.monitor200.EnhancerCommand.enhance(EnhancerCommand.java:173)
	at com.taobao.arthas.core.command.monitor200.EnhancerCommand.process(EnhancerCommand.java:120)
	at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.process(AnnotatedCommandImpl.java:82)
	at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.access$100(AnnotatedCommandImpl.java:18)
	at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:111)
	at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:108)
	at com.taobao.arthas.core.shell.system.impl.ProcessImpl$CommandProcessTask.run(ProcessImpl.java:385)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:840)
Caused by: java.lang.ClassNotFoundException: org.apache.kafka.clients.producer.KafkaProducer$$sw$auxiliary$o9jqgj1
	at java.base/java.net.URLClassLoader.findClass(URLClassLoader.java:445)
	at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:592)
	at com.taobao.arthas.agent.ArthasClassloader.loadClass(ArthasClassloader.java:34)
	at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:525)
	at java.base/java.lang.Class.forName0(Native Method)
	at java.base/java.lang.Class.forName(Class.java:467)
	at com.alibaba.deps.org.objectweb.asm.ClassWriter.getCommonSuperClass(ClassWriter.java:1049)
	... 31 common frames omitted
2023-12-22 11:32:55 [arthas-command-execute] INFO  c.t.arthas.core.advisor.Enhancer -Success to batch transform classes: [class org.apache.kafka.clients.producer.KafkaProducer]

lujiajing1126 · 2023-12-22T08:58:34Z

After discussing with @kylixs, we've confirmed that this PR works well with Arthas 3.6.7, but not versions > 3.6.7 (including 3.7.1, 3.6.8 etc.)

lujiajing1126

This patch LGTM while we could still improve test coverage (probably in the following PRs)

wu-sheng · 2023-12-22T09:23:29Z

Could someone submit a ticket to Arthas? I think they could know this quickly as this is just a diff between versions.

lujiajing1126 · 2023-12-22T09:36:04Z

Could someone submit a ticket to Arthas? I think they could know this quickly as this is just a diff between versions.

Submitted here alibaba/arthas#2774

wu-sheng · 2023-12-22T09:45:01Z

@kylixs Is this possible to makes tests in agent module, rather than Jedis?

And we need to fix change logs, this is not a Jedis fix, but a retransform enhancement, and Arthes compatible fix

kylixs · 2023-12-22T12:11:15Z

Submitted here alibaba/arthas#2774

Fixed: alibaba/arthas#2775

kylixs · 2023-12-22T12:17:32Z

@kylixs Is this possible to makes tests in agent module, rather than Jedis?

And we need to fix change logs, this is not a Jedis fix, but a retransform enhancement, and Arthes compatible fix

I prefer to do a separate module ( agent-retransform-tests ), because there are a lot of plugin-related dependencies. The downside is that we need to maintain some associated dependencies when the plug-in changes.

wu-sheng · 2023-12-22T12:27:08Z

If that is the case, let's keep the test in the Jedis plugin. But let's make changes.md and PR title accurate.

kylixs added 3 commits December 15, 2023 21:00

remove generated methods of superclass and keep generated fields order

9c56e7c

fix version

4c20f34

Add JedisInstrumentationTest

e6d5f1b

wu-sheng added enhancement New feature or request core labels Dec 16, 2023

wu-sheng added this to the 9.2.0 milestone Dec 16, 2023

wu-sheng requested review from lujiajing1126 and wu-sheng December 16, 2023 10:56

Polish code

f32075d

Merge branch 'main' into fix-retransform-jedis

7be889c

lujiajing1126 mentioned this pull request Dec 22, 2023

[Bug] skywalking agent apache/skywalking#11675

Closed

3 tasks

Merge branch 'main' into fix-retransform-jedis

9527b2e

lujiajing1126 previously approved these changes Dec 22, 2023

View reviewed changes

lujiajing1126 mentioned this pull request Dec 22, 2023

Retransform (watch) failed when working with SkyWalking Java Agent for Arthas > 3.6.7 alibaba/arthas#2774

Closed

1 task

kylixs changed the title ~~Fix error in re-transforming the jedis class~~ Fix re-transoform bug when enhanced class proxy parent method Dec 22, 2023

kylixs changed the title ~~Fix re-transoform bug when enhanced class proxy parent method~~ Fix re-transform bug when enhanced class proxy parent method Dec 22, 2023

add change log

64d6814

kylixs dismissed lujiajing1126’s stale review via 64d6814 December 22, 2023 14:05

wu-sheng approved these changes Dec 22, 2023

View reviewed changes

wu-sheng merged commit 4f2f81e into apache:main Dec 22, 2023
187 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix re-transform bug when enhanced class proxy parent method #659

Fix re-transform bug when enhanced class proxy parent method #659

kylixs commented Dec 16, 2023 •

edited

Loading

wu-sheng commented Dec 16, 2023

kylixs commented Dec 16, 2023

kylixs commented Dec 16, 2023

wu-sheng commented Dec 16, 2023

kylixs commented Dec 16, 2023

wu-sheng commented Dec 16, 2023

kylixs commented Dec 16, 2023

wu-sheng commented Dec 16, 2023

kylixs commented Dec 16, 2023

wu-sheng commented Dec 16, 2023

xzyJavaX commented Dec 19, 2023

lujiajing1126 commented Dec 19, 2023

kylixs commented Dec 19, 2023

xzyJavaX commented Dec 19, 2023

wu-sheng commented Dec 20, 2023

kylixs commented Dec 22, 2023 •

edited

Loading

lujiajing1126 commented Dec 22, 2023

lujiajing1126 commented Dec 22, 2023

lujiajing1126 left a comment

wu-sheng commented Dec 22, 2023

lujiajing1126 commented Dec 22, 2023

wu-sheng commented Dec 22, 2023

kylixs commented Dec 22, 2023

kylixs commented Dec 22, 2023

wu-sheng commented Dec 22, 2023

Fix re-transform bug when enhanced class proxy parent method #659

Fix re-transform bug when enhanced class proxy parent method #659

Conversation

kylixs commented Dec 16, 2023 • edited Loading