Created attachment 568541 [details] Server log Description of problem: The testSetGetObject() test method fails on Windows 2008 32b and Windows 2008 R2 64bit. The test method can be found at https://svn.devel.redhat.com/repos/jboss-qa/edg/edg-functional-tests/trunk/core-tests/src/test/java/org/jboss/test/cluster/datagrid/memcached/MemcachedClientTestCase.java and looks like this: @Test public void testSetGetObject() throws Exception { ByteArrayOutputStream bout = new ByteArrayOutputStream(); ObjectOutputStream oo = new ObjectOutputStream(bout); oo.writeObject(new TestSerializable("CONTENT")); oo.flush(); byte[] byteData = bout.toByteArray(); mc.writeln("set " + KEY_A + " 0 0 " + byteData.length); mc.flush(); mc.write(byteData); mc.write("\r\n".getBytes(ENCODING)); mc.flush(); assertEquals("STORED", mc.readln()); byte[] bytesBack = mc.getBytes(KEY_A); assertEquals(byteData.length, bytesBack.length); ObjectInputStream oin = new ObjectInputStream(new ByteArrayInputStream(bytesBack)); TestSerializable ts = (TestSerializable) oin.readObject(); assertEquals("CONTENT", ts.getContent()); } The test method fails at line assertEquals(byteData.length, bytesBack.length); where I get NullPointerException Attaching server.log and surefire report. How reproducible: Run functional tests in core-tests submodule.
Created attachment 568542 [details] Surefire report The surefire report says that it fails on line 132, please ignore that as I added some more lines before running the test. It actually fails on line specified in the description of this BZ
Could you please rerun this with trace logs enabled for org.infinispan.server.memcached
Created attachment 568906 [details] TRACE log solaris 10 x64 java6 I found this issue on Solaris too. I attached trace log from run on Solaris 10 x64 (Hudson slave dev20-01-solaris10-x86) with this java: java version "1.6.0_24" Java(TM) SE Runtime Environment (build 1.6.0_24-b07) Java HotSpot(TM) Server VM (build 19.1-b02, mixed mode)
The problem is that the server is receiving a null command for the preceding set operation, and therefore it breaks when performing the get. I will investigate this further
Would it be possible to get pcaps using wireshark of test ? Also could you try running just that single test ?
Technical note added. If any revisions are required, please edit the "Technical Notes" field accordingly. All revisions will be proofread by the Engineering Content Services team. New Contents: CCFR - Tristan
Technical note updated. If any revisions are required, please edit the "Technical Notes" field accordingly. All revisions will be proofread by the Engineering Content Services team. Diffed Contents: @@ -1 +1 @@ -CCFR - Tristan+When running the server on Windows and Solaris occasionally the storage of a byte array is misinterpreted by the server as an invalid command. This does not happen under RHEL.
Technical note updated. If any revisions are required, please edit the "Technical Notes" field accordingly. All revisions will be proofread by the Engineering Content Services team. Diffed Contents: @@ -1 +1 @@ -When running the server on Windows and Solaris occasionally the storage of a byte array is misinterpreted by the server as an invalid command. This does not happen under RHEL.+When running the server on Windows and Solaris, a byte array's storage is occasionally misinterpreted by the server as an invalid command. This does not occur when the server runs on Red Hat Enterprise Linux.
Created attachment 582391 [details] pcap of testSetGetObject method in distributuon mode
Created attachment 582392 [details] pcap of testSetGetObject method in replication mode
Created attachment 582393 [details] pcap of testSetGetObject method in local mode
Hi Tristan, I have added three small gifts for you :-) You can see packet capture of MemcachedClientTestCase.testSetGetObject test method. I have run and capture packets in distribution, replication and local mode. I successfully opened attached files in wireshark-gnome so I suppose it could be fine for you too. I hope this will help you. In any case ask more/detailed info. Once again sorry for my delay I was blocked by more urgent tasks until this time. Configuration: OS: Microsoft Windows Server 2008 R2 enterprise version 6.1.7601 Service Pack 1 Build 7601 x64-based PC Java: jdk1.6.0_27 Note: I was not able to reproduce this problem on the same system 32 bit architecture system. Test was run more than 5 times in all modes. Maybe only bad probability... But on x64 win failed every time in all modes when I was running test manually. (In Hudson - it depends - unpredictable behaviour) Note2: We can see this problem on Solaris machines too. But I can't pcap loopback on solaris lo0 interface. That is not possible according to internet-info.
The only pcap that makes sense in Wireshark is the local mode one (which should be enough). The sequence of messages in the pcap is as follows (binary data removed for clarity): REQUEST set a 0 0 136 srJcom.jboss.datagrid.test.memcached.MemcachedClientTestCase$TestSerializable?XT3LcontenttLjava/lang/String;xptCONTENT RESPONSE STORED REQUEST get a RESPONSE ERROR RESPONSE VALUE a 0 136 srJcom.jboss.datagrid.test.memcached.MemcachedClientTestCase$TestSerializable?XT3LcontenttLjava/lang/String;xptCONTENT END As you can see the server is attempting to reply correctly to the "get a" command, but for some reason a spurious "ERROR" response happens before the "VALUE" response causing the client to get confused. Galder, any insight ?
Tomas, ideally it would be great if the attached pcap and "trace" server log could come from the same run (the server.log above tell us that the server is processing a set for a 144 byte payload, whereas the pcap shows a 136 byte payload (that may be because of serialization differences).
Created attachment 582669 [details] server "trace" log from the same run as next pcap (1)
Created attachment 582672 [details] pcap of testSetGetObject method in local mode - the same run as server log (1) Hi Tristan, In case of any problems let me know I would try to provide any other logs or information. It was run on the same configuration as last time and both logs are from the same one run of that method.
Tomas, can't find https://svn.devel.redhat.com/repos/jboss-qa/edg/edg-functional-tests/trunk/core-tests/src/test/java/org/jboss/test/cluster/datagrid/memcached/MemcachedClientTestCase.java, where is that? Can you try a few things separately? I don't know what mc.writeln really does, but bearing in mind that, try this: 1. Switch the following line: mc.writeln("set " + KEY_A + " 0 0 " + byteData.length); for: mc.writeln("set " + KEY_A + " 0 0 " + byteData.length + " "); See if that works. 2. If that doesn't work, try using something else other than writeln, in case this is a plattform dependent method: // convert the following to UTF-8: "set " + KEY_A + " 0 0 " + byteData.length + "\r\n" And the call: mc.write(set); 3. If that doesn't work, try: // convert the following to UTF-8: "set " + KEY_A + " 0 0 " + byteData.length + " \r\n" mc.write(set); Cheers,
Galder, the tests now live here: https://svn.devel.redhat.com/repos/jboss-qa/jdg/jdg-functional-tests/trunk/remote/
Per Tristan triage, moved from ER8 to ER9 target release.
Galder Hi! Thank you for your suggestions. I have carefully tried all of them on same configuration as last time. If I add " " space (2 cases): 1) mc.writeln("set " + KEY_A + " 0 0 " + byteData.length + " "); 2) to UTF-8: "set " + KEY_A + " 0 0 " + byteData.length + " \r\n" it doesn't work. We can see this error on console: 07:07:44,326 ERROR [org.infinispan.server.memcached.MemcachedDecoder] (HotRodServerWorker-1-1) ISPN005003: Exception rep orted: java.io.StreamCorruptedException: Unable to parse noreply optional argument and this in surefire report: org.junit.ComparisonFailure: expected:<[STORED]> but was:<[CLIENT_ERROR bad command line format: Unable to parse noreply optional argument]> at this this line: assertEquals("STORED", mc.readln()); last case: // convert the following to UTF-8: "set " + KEY_A + " 0 0 " + byteData.length + "\r\n" unfortunately doesn't work either. Same error as Martin mentioned. NullPointerException at line assertEquals(byteData.length, bytesBack.length); Please see related links: (for write and writeln methods) https://svn.devel.redhat.com/repos/jboss-qa/jdg/jdg-functional-tests/trunk/remote/common-utils/src/main/java/com/jboss/datagrid/test/utils/memcached/MemcachedHelper.java (for testSetGetObject method) https://svn.devel.redhat.com/repos/jboss-qa/jdg/jdg-functional-tests/trunk/remote/core-tests/src/test/java/com/jboss/datagrid/test/memcached/MemcachedClientTestCase.java If any log/info needed I will provide it asap.
Tried with ER9 on Windows x64 and I could not reproduce the problem.
ER9 on Solaris10 x86 + sunjdk6+7 and Windows x64 sunjdk7 --> I can still reproduce this issue occasionally. It seems to be unpredictable. (For proper verification we need to run this method MORE times in a row to be sure about this.)
ER10: Can't replicate this anymore. Setting as verified.
This bug is flagged for addition to JDG 6 GA. Flagging a NEEDINFO for assignee for information about the fix and to correct the identified problem (technical notes box), if required.
Since this is not an issue anymore, removing the technical notes.
Deleted Technical Notes Contents. Old Contents: When running the server on Windows and Solaris, a byte array's storage is occasionally misinterpreted by the server as an invalid command. This does not occur when the server runs on Red Hat Enterprise Linux.
The issue was caused by the memcached server not always consuming the CR/LF delimiter which marks the end of a client request. The server then attempted to decode the delimiter as the header of the following request and incorrectly reported this as a bad message
Technical note added. If any revisions are required, please edit the "Technical Notes" field accordingly. All revisions will be proofread by the Engineering Content Services team. New Contents: When running the server on Windows and Solaris, a byte array's storage was occasionally misinterpreted by the server as an invalid command. This was caused by the memcached server not always consuming the CR/LF delimiter which marks the end of a client request. The server then attempted to decode the delimiter as the header of the following request and incorrectly reported this as a bad message. This is now fixed and running the server on Windows and Solaris now operates as expected.
Misha, I updated the tech note: the problem actually happened on all platforms (just not as frequently on RHEL), so I removed all references to Windows and Solaris
Technical note updated. If any revisions are required, please edit the "Technical Notes" field accordingly. All revisions will be proofread by the Engineering Content Services team. Diffed Contents: @@ -1 +1 @@ -When running the server on Windows and Solaris, a byte array's storage was occasionally misinterpreted by the server as an invalid command. This was caused by the memcached server not always consuming the CR/LF delimiter which marks the end of a client request. The server then attempted to decode the delimiter as the header of the following request and incorrectly reported this as a bad message. This is now fixed and running the server on Windows and Solaris now operates as expected.+A byte array's storage was occasionally misinterpreted by the server as an invalid command. This was caused by the memcached server not always consuming the CR/LF delimiter which marks the end of a client request. The server then attempted to decode the delimiter as the header of the following request and incorrectly reported this as a bad message. This is now fixed and running the server operates as expected.