search

opentracing-contrib / java-specialagent

Automatic instrumentation for 3rd-party libraries in Java applications with OpenTracing.
Apache License 2.0
185 stars 46 forks source link

`spymemcached` integration test failing for jdk1.8 #480

Closed safris closed 4 years ago

safris commented 4 years ago

I'm getting this consistently on my local machine when running in test/spymemcached:

Initialized SpecialAgent in 14.96s

SpecialAgent.linkRule("concurrent"[50], null): compatible = null, RulePath: /var/folders/zb/xjqqmfc54zq8xhdlq48jbz400000gn/T/opentracing-specialagent5281407322500609785/META-INF/plugins/concurrent-1.6.0-SNAPSHOT.jar
Allowing instrumentation with "concurrent" due to "fingerprint.bin match" for:
file:/var/folders/zb/xjqqmfc54zq8xhdlq48jbz400000gn/T/opentracing-specialagent5281407322500609785/META-INF/plugins/concurrent-1.6.0-SNAPSHOT.jar
[concurrent] Target class loader is: null (bootstrap)
[concurrent] Injection of instrumentation classes called
SpecialAgent.linkRule("concurrent"[50], null): compatible = true [cached]
SpecialAgent.linkRule("spymemcached"[46], sun.misc.Launcher$AppClassLoader@18b4aac2): compatible = null, RulePath: /var/folders/zb/xjqqmfc54zq8xhdlq48jbz400000gn/T/opentracing-specialagent5281407322500609785/META-INF/plugins/spymemcached-1.6.0-SNAPSHOT.jar
ClassFingerprint#compatible[true]("net.spy.memcached.ops.GetAndTouchOperation$Callback")
ClassFingerprint#compatible[true]("net.spy.memcached.ops.OperationCallback")
ClassFingerprint#compatible[true]("net.spy.memcached.ops.StoreOperation$Callback")
ClassFingerprint#compatible[true]("net.spy.memcached.ops.GetOperation$Callback")
ClassFingerprint#compatible[true]("net.spy.memcached.ops.GetsOperation$Callback")
ClassFingerprint#compatible[true]("net.spy.memcached.ops.DeleteOperation$Callback")
ClassFingerprint#compatible[true]("net.spy.memcached.ops.OperationStatus")
Allowing instrumentation with "spymemcached" due to "fingerprint.bin match" for:
file:/var/folders/zb/xjqqmfc54zq8xhdlq48jbz400000gn/T/opentracing-specialagent5281407322500609785/META-INF/plugins/spymemcached-1.6.0-SNAPSHOT.jar
[spymemcached] Target class loader is: sun.misc.Launcher$AppClassLoader@18b4aac2 (system)
[spymemcached] Injection of instrumentation classes deferred
SpecialAgent.linkRule("spymemcached"[46], sun.misc.Launcher$AppClassLoader@18b4aac2): compatible = true [cached]
SpecialAgent.linkRule("thread"[103], sun.misc.Launcher$AppClassLoader@18b4aac2): compatible = null, RulePath: /var/folders/zb/xjqqmfc54zq8xhdlq48jbz400000gn/T/opentracing-specialagent5281407322500609785/META-INF/plugins/thread-1.6.0-SNAPSHOT.jar
Allowing instrumentation with "thread" due to "fingerprint.bin match" for:
file:/var/folders/zb/xjqqmfc54zq8xhdlq48jbz400000gn/T/opentracing-specialagent5281407322500609785/META-INF/plugins/thread-1.6.0-SNAPSHOT.jar
[thread] Target class loader is: sun.misc.Launcher$AppClassLoader@18b4aac2 (system)
[thread] Injection of instrumentation classes deferred
SpecialAgent.linkRule("thread"[103], sun.misc.Launcher$AppClassLoader@18b4aac2): compatible = true [cached]
2020-03-11 21:33:11.057 INFO net.spy.memcached.MemcachedConnection:  Added {QA sa=localhost/127.0.0.1:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue
-------> Intercept [ThreadAgentRule@main]: public synchronized void java.lang.Thread.start()
-------> Intercept [ThreadAgentRule@Memcached IO over {MemcachedConnection to localhost/127.0.0.1:11211}]: public void net.spy.memcached.MemcachedConnection.run()
2020-03-11 21:33:11.099 INFO net.spy.memcached.MemcachedConnection:  Connection state changed for sun.nio.ch.SelectionKeyImpl@456c528c
2020-03-11 21:33:11.101 INFO net.spy.memcached.MemcachedConnection:  Reconnecting due to failure to connect to {QA sa=localhost/127.0.0.1:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}
java.net.ConnectException: Connection refused
    at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
    at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717)
    at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:641)
    at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:418)
    at net.spy.memcached.MemcachedConnection.run(MemcachedConnection.java:1400)
2020-03-11 21:33:11.123 WARN net.spy.memcached.MemcachedConnection:  Closing, and reopening {QA sa=localhost/127.0.0.1:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}, attempt 1.
-------> Intercept [SpymemcachedAgentRule@main]: public net.spy.memcached.ops.StoreOperation net.spy.memcached.protocol.ascii.AsciiOperationFactory.store(net.spy.memcached.ops.StoreType,java.lang.String,int,int,byte[],net.spy.memcached.ops.StoreOperation$Callback)
SpecialAgent.linkRule("spymemcached"[46], sun.misc.Launcher$AppClassLoader@18b4aac2): compatible = true [cached]
2020-03-11 21:33:11.360 WARN net.spy.memcached.MemcachedConnection:  Could not redistribute to another node, retrying primary node for key.
2020-03-11 21:33:15.129 INFO net.spy.memcached.MemcachedConnection:  Reconnecting {QA sa=localhost/127.0.0.1:11211, #Rops=0, #Wops=1, #iq=0, topRop=null, topWop=Cmd: set Key: key Flags: 0 Exp: 120 Data Length: 5, toWrite=0, interested=0}
2020-03-11 21:33:15.130 INFO net.spy.memcached.MemcachedConnection:  Connection state changed for sun.nio.ch.SelectionKeyImpl@363dcd0
2020-03-11 21:33:15.130 INFO net.spy.memcached.MemcachedConnection:  Reconnecting due to failure to connect to {QA sa=localhost/127.0.0.1:11211, #Rops=0, #Wops=1, #iq=0, topRop=null, topWop=Cmd: set Key: key Flags: 0 Exp: 120 Data Length: 5, toWrite=0, interested=0}
java.net.ConnectException: Connection refused
    at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
    at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717)
    at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:641)
    at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:418)
    at net.spy.memcached.MemcachedConnection.run(MemcachedConnection.java:1400)
2020-03-11 21:33:15.131 WARN net.spy.memcached.MemcachedConnection:  Closing, and reopening {QA sa=localhost/127.0.0.1:11211, #Rops=0, #Wops=1, #iq=0, topRop=null, topWop=Cmd: set Key: key Flags: 0 Exp: 120 Data Length: 5, toWrite=0, interested=0}, attempt 2.
2020-03-11 21:33:23.137 INFO net.spy.memcached.MemcachedConnection:  Reconnecting {QA sa=localhost/127.0.0.1:11211, #Rops=0, #Wops=1, #iq=0, topRop=null, topWop=Cmd: set Key: key Flags: 0 Exp: 120 Data Length: 5, toWrite=0, interested=0}
2020-03-11 21:33:23.138 INFO net.spy.memcached.MemcachedConnection:  Connection state changed for sun.nio.ch.SelectionKeyImpl@7f38ca21
2020-03-11 21:33:23.138 INFO net.spy.memcached.MemcachedConnection:  Reconnecting due to failure to connect to {QA sa=localhost/127.0.0.1:11211, #Rops=0, #Wops=1, #iq=0, topRop=null, topWop=Cmd: set Key: key Flags: 0 Exp: 120 Data Length: 5, toWrite=0, interested=0}
java.net.ConnectException: Connection refused
    at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
    at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717)
    at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:641)
    at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:418)
    at net.spy.memcached.MemcachedConnection.run(MemcachedConnection.java:1400)
2020-03-11 21:33:23.139 WARN net.spy.memcached.MemcachedConnection:  Closing, and reopening {QA sa=localhost/127.0.0.1:11211, #Rops=0, #Wops=1, #iq=0, topRop=null, topWop=Cmd: set Key: key Flags: 0 Exp: 120 Data Length: 5, toWrite=0, interested=0}, attempt 3.
java.lang.reflect.InvocationTargetException
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.codehaus.mojo.exec.Exec.main(Exec.java:26)
Caused by: net.spy.memcached.internal.CheckedOperationTimeoutException: Timed out waiting for operation - failing node: localhost/127.0.0.1:11211
    at net.spy.memcached.internal.OperationFuture.get(OperationFuture.java:167)
    at io.opentracing.contrib.specialagent.test.spymemcached.SpymemcachedITest.main(SpymemcachedITest.java:28)
    ... 5 more
-------> Intercept [ThreadAgentRule@main]: public synchronized void java.lang.Thread.start()
-------> Intercept [ThreadAgentRule@Thread-0]: public void io.opentracing.contrib.specialagent.SpecialAgentUtil$ShutdownHook.run()
-------> Intercept [ThreadAgentRule@Thread-0]: public void io.opentracing.contrib.specialagent.SpecialAgentUtil$ShutdownHook.run()
-------> Intercept [ThreadAgentRule@Thread-0]: public void io.opentracing.contrib.specialagent.SpecialAgentUtil$ShutdownHook.run()
[ERROR] Command execution failed.
org.apache.commons.exec.ExecuteException: Process exited with an error: 1 (Exit value: 1)
    at org.apache.commons.exec.DefaultExecutor.executeInternal (DefaultExecutor.java:404)
    at org.apache.commons.exec.DefaultExecutor.execute (DefaultExecutor.java:166)
    at org.codehaus.mojo.exec.ExecMojo.executeCommandLine (ExecMojo.java:804)
    at org.codehaus.mojo.exec.ExecMojo.executeCommandLine (ExecMojo.java:751)
    at org.codehaus.mojo.exec.ExecMojo.execute (ExecMojo.java:313)
    at org.codehaus.mojo.exec.ITestMojo.execute (ITestMojo.java:212)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo (DefaultBuildPluginManager.java:137)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:210)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:156)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:148)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject (LifecycleModuleBuilder.java:117)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject (LifecycleModuleBuilder.java:81)
    at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build (SingleThreadedBuilder.java:56)
    at org.apache.maven.lifecycle.internal.LifecycleStarter.execute (LifecycleStarter.java:128)
    at org.apache.maven.DefaultMaven.doExecute (DefaultMaven.java:305)
    at org.apache.maven.DefaultMaven.doExecute (DefaultMaven.java:192)
    at org.apache.maven.DefaultMaven.execute (DefaultMaven.java:105)
    at org.apache.maven.cli.MavenCli.execute (MavenCli.java:957)
    at org.apache.maven.cli.MavenCli.doMain (MavenCli.java:289)
    at org.apache.maven.cli.MavenCli.main (MavenCli.java:193)
    at sun.reflect.NativeMethodAccessorImpl.invoke0 (Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke (NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke (DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke (Method.java:498)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced (Launcher.java:282)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launch (Launcher.java:225)
    at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode (Launcher.java:406)
    at org.codehaus.plexus.classworlds.launcher.Launcher.main (Launcher.java:347)
malafeev commented 4 years ago

@safris you need to start Memcached service on your machine to pass this test. in travis it's already running.

safris commented 4 years ago

Oh, how do I do that?

malafeev commented 4 years ago

something like brew install memcached && memcached

safris commented 4 years ago

Can you document this in the spymemcached/README.md?

malafeev commented 4 years ago

test/spymemcached/README.md ?

safris commented 4 years ago

Or, even better, in the code... Just did it.

malafeev commented 4 years ago

@safris so no need for test/spymemcached/README.md ?

safris commented 4 years ago

No need!