[jcifs] SmbComWriteAndX writes corrupt offset to wire
Richard Heap
richardheap at beeb.net
Wed Apr 14 21:56:47 GMT 2004
This is one of those things that you hope you never have to write, but
I'm feeling "compiler bug" (well JVM bug to be precise).
Firstly 0.9.0p3 doesn't seem to make much difference
Finally, I have a test harness that reproduces the problem (but it's
real elusive...)
Ok, so back to the facts...
Here's the first occurance of corruption in the logfile of a test run.
2004-04-14 12:53:54,441 ERROR [STDERR] queue.name.eqb:
writeParameterWordsWireFormat: offset=4000
2004-04-14 12:53:54,441 ERROR [STDERR] 00000: FF 53 4D 42 2F 00 00 00 00
18 03 80 00 00 00 00 |ÿSMB/...........|
00010: 00 00 00 00 00 00 00 00 02 30 0B 70 01 68 5F 0D |.........0.p.h_.|
00020: 0E FF 00 00 00 0E C0 00 0F 00 00 00 00 00 00 00 |.ÿ....À.........|
00030: 00 00 00 00 00 A0 0F 3F 00 00 00 00 |..... .?.... |
2004-04-14 12:53:54,441 ERROR [STDERR] queue.name.eqb: writeAndXWireFormat1
2004-04-14 12:53:54,441 ERROR [STDERR] 00000: FF 53 4D 42 2F 00 00 00 00
18 03 80 00 00 00 00 |ÿSMB/...........|
00010: 00 00 00 00 00 00 00 00 02 30 0B 70 01 68 5F 0D |.........0.p.h_.|
00020: 0E FF 00 00 00 0E C0 00 0F 00 00 00 00 00 00 00 |.ÿ....À.........|
00030: 00 00 00 00 00 A0 0F 3F 00 00 00 00 00 A0 0F |..... .?..... . |
2004-04-14 12:53:54,441 ERROR [STDERR] queue.name.eqb: writeWireFormat
2004-04-14 12:53:54,441 ERROR [STDERR] 00000: FF 53 4D 42 2F 00 00 00 00
18 03 80 00 00 00 00 |ÿSMB/...........|
00010: 00 00 00 00 00 00 00 00 02 30 0B 70 01 68 5F 0D |.........0.p.h_.|
00020: 0E FF 00 00 00 0E C0 00 0F 00 00 00 00 00 00 00 |.ÿ....À.........|
00030: 00 00 00 00 00 A0 0F 3F 00 00 00 00 00 A0 0F |..... .?..... . |
2004-04-14 12:53:54,441 ERROR [STDERR] queue.name.eqb:
SmbComWriteAndX[command=SMB_COM_WRITE_ANDX,received=false,errorCode=0x00000000,flags=0x0018,flags2=0x8003,tid=12290,pid=28683,uid=26625,mid=3423,wordCount=14,byteCount=4000,andxCommand=0xFF,andxOffset=0,fid=49166,offset=4000,writeMode=0,remaining=0,dataLength=4000,dataOffset=63]
Note how the offset is corrupt even directly after
writeParameterWordsWireFormat
The interesting thing is that I have found the 'trigger' that causes it
to 'break'. The previous file copied is longer than normal, and, in
fact, the offset breaks half way through the file, as follows....
2004-04-14 12:53:53,803 ERROR [STDERR] queue.name.eqb:
writeParameterWordsWireFormat: offset=92000
2004-04-14 12:53:53,804 ERROR [STDERR] 00000: FF 53 4D 42 2F 00 00 00 00
18 03 80 00 00 00 00 |ÿSMB/...........|
00010: 00 00 00 00 00 00 00 00 02 30 0B 70 01 68 0B 0D |.........0.p.h..|
00020: 0E FF 00 00 00 0D C0 60 67 01 00 00 00 00 00 00 |.ÿ....À`g.......|
00030: 00 00 00 00 00 A0 0F 3F 00 00 00 00 |..... .?.... |
2004-04-14 12:53:53,804 ERROR [STDERR] queue.name.eqb: writeAndXWireFormat1
2004-04-14 12:53:53,804 ERROR [STDERR] 00000: FF 53 4D 42 2F 00 00 00 00
18 03 80 00 00 00 00 |ÿSMB/...........|
00010: 00 00 00 00 00 00 00 00 02 30 0B 70 01 68 0B 0D |.........0.p.h..|
00020: 0E FF 00 00 00 0D C0 60 67 01 00 00 00 00 00 00 |.ÿ....À`g.......|
00030: 00 00 00 00 00 A0 0F 3F 00 00 00 00 00 A0 0F |..... .?..... . |
2004-04-14 12:53:53,804 ERROR [STDERR] queue.name.eqb: writeWireFormat
2004-04-14 12:53:53,804 ERROR [STDERR] 00000: FF 53 4D 42 2F 00 00 00 00
18 03 80 00 00 00 00 |ÿSMB/...........|
00010: 00 00 00 00 00 00 00 00 02 30 0B 70 01 68 0B 0D |.........0.p.h..|
00020: 0E FF 00 00 00 0D C0 60 67 01 00 00 00 00 00 00 |.ÿ....À`g.......|
00030: 00 00 00 00 00 A0 0F 3F 00 00 00 00 00 A0 0F |..... .?..... . |
2004-04-14 12:53:53,804 ERROR [STDERR] queue.name.eqb:
SmbComWriteAndX[command=SMB_COM_WRITE_ANDX,received=false,errorCode=0x00000000,flags=0x0018,flags2=0x8003,tid=12290,pid=28683,uid=26625,mid=3339,wordCount=14,byteCount=4000,andxCommand=0xFF,andxOffset=0,fid=49165,offset=92000,writeMode=0,remaining=0,dataLength=4000,dataOffset=63]
2004-04-14 12:53:53,804 ERROR [STDERR] 00000: FF 53 4D 42 2F 00 00 00 00
18 03 80 00 00 00 00 |ÿSMB/...........|
00010: 00 00 00 00 00 00 00 00 02 30 0B 70 01 68 0B 0D |.........0.p.h..|
00020: 0E FF 00 00 00 0D C0 60 67 01 00 00 00 00 00 00 |.ÿ....À`g.......|
00030: 00 00 00 00 00 A0 0F 3F 00 00 00 00 00 A0 0F |..... .?..... . |
2004-04-14 12:53:53,823 ERROR [STDERR] queue.name.eqb:
writeParameterWordsWireFormat: offset=96000
2004-04-14 12:53:53,823 ERROR [STDERR] 00000: FF 53 4D 42 2F 00 00 00 00
18 03 80 00 00 00 00 |ÿSMB/...........|
00010: 00 00 00 00 00 00 00 00 02 30 0B 70 01 68 0C 0D |.........0.p.h..|
00020: 0E FF 00 00 00 0D C0 00 77 01 00 00 00 00 00 00 |.ÿ....À.w.......|
00030: 00 00 00 00 00 A0 0F 3F 00 00 00 00 |..... .?.... |
2004-04-14 12:53:53,823 ERROR [STDERR] queue.name.eqb: writeAndXWireFormat1
2004-04-14 12:53:53,823 ERROR [STDERR] 00000: FF 53 4D 42 2F 00 00 00 00
18 03 80 00 00 00 00 |ÿSMB/...........|
00010: 00 00 00 00 00 00 00 00 02 30 0B 70 01 68 0C 0D |.........0.p.h..|
00020: 0E FF 00 00 00 0D C0 00 77 01 00 00 00 00 00 00 |.ÿ....À.w.......|
00030: 00 00 00 00 00 A0 0F 3F 00 00 00 00 00 A0 0F |..... .?..... . |
2004-04-14 12:53:53,823 ERROR [STDERR] queue.name.eqb: writeWireFormat
2004-04-14 12:53:53,824 ERROR [STDERR] 00000: FF 53 4D 42 2F 00 00 00 00
18 03 80 00 00 00 00 |ÿSMB/...........|
00010: 00 00 00 00 00 00 00 00 02 30 0B 70 01 68 0C 0D |.........0.p.h..|
00020: 0E FF 00 00 00 0D C0 00 77 01 00 00 00 00 00 00 |.ÿ....À.w.......|
00030: 00 00 00 00 00 A0 0F 3F 00 00 00 00 00 A0 0F |..... .?..... . |
2004-04-14 12:53:53,824 ERROR [STDERR] queue.name.eqb:
SmbComWriteAndX[command=SMB_COM_WRITE_ANDX,received=false,errorCode=0x00000000,flags=0x0018,flags2=0x8003,tid=12290,pid=28683,uid=26625,mid=3340,wordCount=14,byteCount=4000,andxCommand=0xFF,andxOffset=0,fid=49165,offset=96000,writeMode=0,remaining=0,dataLength=4000,dataOffset=63]
2004-04-14 12:53:53,824 ERROR [STDERR] 00000: FF 53 4D 42 2F 00 00 00 00
18 03 80 00 00 00 00 |ÿSMB/...........|
00010: 00 00 00 00 00 00 00 00 02 30 0B 70 01 68 0C 0D |.........0.p.h..|
00020: 0E FF 00 00 00 0D C0 00 77 01 00 00 00 00 00 00 |.ÿ....À.w.......|
00030: 00 00 00 00 00 A0 0F 3F 00 00 00 00 00 A0 0F |..... .?..... . |
2004-04-14 12:53:53,845 ERROR [STDERR] queue.name.eqb:
writeParameterWordsWireFormat: offset=100000
2004-04-14 12:53:54,244 ERROR [STDERR] 00000: FF 53 4D 42 2F 00 00 00 00
18 03 80 00 00 00 00 |ÿSMB/...........|
00010: 00 00 00 00 00 00 00 00 02 30 0B 70 01 68 0D 0D |.........0.p.h..|
00020: 0E FF 00 00 00 0D C0 00 86 01 00 00 00 00 00 00 |.ÿ....À.........|
00030: 00 00 00 00 00 A0 0F 3F 00 00 00 00 |..... .?.... |
2004-04-14 12:53:54,245 ERROR [STDERR] queue.name.eqb: writeAndXWireFormat1
2004-04-14 12:53:54,245 ERROR [STDERR] 00000: FF 53 4D 42 2F 00 00 00 00
18 03 80 00 00 00 00 |ÿSMB/...........|
00010: 00 00 00 00 00 00 00 00 02 30 0B 70 01 68 0D 0D |.........0.p.h..|
00020: 0E FF 00 00 00 0D C0 00 86 01 00 00 00 00 00 00 |.ÿ....À.........|
00030: 00 00 00 00 00 A0 0F 3F 00 00 00 00 00 A0 0F |..... .?..... . |
2004-04-14 12:53:54,245 ERROR [STDERR] queue.name.eqb: writeWireFormat
2004-04-14 12:53:54,245 ERROR [STDERR] 00000: FF 53 4D 42 2F 00 00 00 00
18 03 80 00 00 00 00 |ÿSMB/...........|
00010: 00 00 00 00 00 00 00 00 02 30 0B 70 01 68 0D 0D |.........0.p.h..|
00020: 0E FF 00 00 00 0D C0 00 86 01 00 00 00 00 00 00 |.ÿ....À.........|
00030: 00 00 00 00 00 A0 0F 3F 00 00 00 00 00 A0 0F |..... .?..... . |
2004-04-14 12:53:54,245 ERROR [STDERR] queue.name.eqb:
SmbComWriteAndX[command=SMB_COM_WRITE_ANDX,received=false,errorCode=0x00000000,flags=0x0018,flags2=0x8003,tid=12290,pid=28683,uid=26625,mid=3341,wordCount=14,byteCount=4000,andxCommand=0xFF,andxOffset=0,fid=49165,offset=100000,writeMode=0,remaining=0,dataLength=4000,dataOffset=63]
Notice how 92000 is encoded ok, 100000 is encoded incorrectly. Of
course, it's impossible to tell if 96000 is encoded correctly, as it
happens to have a 0 byte naturally.
This longer than normal file seems to be the trigger that permanently
breaks the encoding.
So back to the test harness - now modified to throw in a few files >
100000 bytes. It won't break on Windows at all, and it won't break with
the client JVM on linux. It only breaks with the -server option. I've
tried 1.4.2_01 and 1.4.2_04 - same result. I'm downloading 1.5 at the
moment to see if that changes anything. (And just about to test the real
application without -server). Will let you know.
Many Thanks
Richard
Michael B Allen wrote:
>Hi Richard,
>
>
>
>>After the server has been running for a few 10s of minutes we notice
>>that the files written to the share are corrupt. It seems that files are
>>initially copied ok, and then something 'breaks'. An ethereal trace
>>shows that the offset of the server-bound WriteAndX messages is corrupt.
>>
>>
>
>So once it happends it never corrects itself? That's strange because
>you would think that provided the SmbFileOutputStream is closed and is
>used exclusively by a single thread that any state associated with that
>object would be reset when the next object was created. Has to be related
>to some static variable/object.
>
>
>
>>The following code...
>>byte[] buffer = new byte[4000];
>>while ((int length = in.read(buffer)) > 0) {
>> out.write(buffer, 0, length);
>>}
>>produces WriteAndX messages with the following offsets...
>>0, 3840, 7936, etc (instead of 0, 4000, 8000)
>>in hex these values are: 0x0F00 and 0x1F00 (should be 0x0FA0 and 0x1F40
>>- i.e. it appears that the bottom byte is being squashed to zero)
>>
>>This appears to be confirmed by the following ALL level log:
>>Apr 9 12:25:53.107 - smb sent
>>SmbComWriteAndX[command=SMB_COM_WRITE_ANDX,received=false,
>>errorCode=0x00000000,flags=0x0018,flags2=0x8003,tid=28677,pid=22517,
>>uid=57345,mid=2957,wordCount=14,byteCount=4000,andxCommand=0xFF,
>>andxOffset=0,fid=9,offset=4000,writeMode=0,remaining=0,dataLength=4000,
>>dataOffset=63]
>>Apr 9 12:25:53.107 - smb sent
>>00000: FF 53 4D 42 2F 00 00 00 00 18 03 80 00 00 00 00 |ÿSMB/...........|
>>00010: 00 00 00 00 00 00 00 00 05 70 F5 57 01 E0 8D 0B |.........põW.à..|
>>00020: 0E FF 00 00 00 09 00 00 0F 00 00 00 00 00 00 00 |.ÿ..............|
>>00030: 00 00 00 00 00 A0 0F 3F 00 00 00 00 00 A0 0F 58 |..... .?..... .X|
>>
>>
>
>That's very interesting. It looks like an encoding error. Unfortunately
>I have spend several hours trying to track this down without any luck. I
>do not see anything obviously wrong with the encoding routines and I have
>created a test program that writes 259760 byte file to a server every
>800ms and then reads it back every 3 seconds. After letting it run for a
>good hour with -Xmx500k for a while now I'm not seeing any problems.
>
>
>
>>What is interesting is that the toString() of the SmbComWriteAndX still
>>shows 4000, yet the hex dump shows 00 0F 00 00 (decimal 3840)
>>
>>
>
>Yes it is. Good catch. It might be critically important. Can you try this
>jar?
>
> http://home.comcast.net/~miallen1/jcifs/jcifs-0.8.2x.jar
>
>Maybe we can zoom in on where the encoding error. Don't run with
>log=ALL. It has very selective debugging statements hardcoded in
>it. Basically the encoding routines for SmbComWriteAndX are called like:
>
>writeWireFormat
> writeHeaderWriteFormat
> writeAndXWireFormat
> writeParameterWordsWireFormat
> writeBytesWireFormat
>
>The offset is encoded in writeParameterWordsWireFormat but I suspect
>it could be that it's encoded properly there only to be clobbered
>by something or someone else. So I have placed hexdump calls at the
>end of writeWireFormat, at the end of writeAndXWireFormat, and end
>of writeParameterWordsWireFormat. The System.err output should looks
>something like this:
>
>main: writeParameterWordsWireFormat: offset=188000
>00000: FF 53 4D 42 2F 00 00 00 00 18 03 80 00 00 00 00 |ÿSMB/...........|
>00010: 00 00 00 00 00 00 00 00 00 08 6B 12 00 08 DF 16 |..........k...ß.|
>00020: 0E FF 00 00 00 07 30 60 DE 02 00 00 00 00 00 00 |.ÿ....0`Þ.......|
>00030: 00 00 00 00 00 A0 0F 3F 00 00 00 00 |..... .?.... |
>
>main: writeAndXWireFormat1
>00000: FF 53 4D 42 2F 00 00 00 00 18 03 80 00 00 00 00 |ÿSMB/...........|
>00010: 00 00 00 00 00 00 00 00 00 08 6B 12 00 08 DF 16 |..........k...ß.|
>00020: 0E FF 00 00 00 07 30 60 DE 02 00 00 00 00 00 00 |.ÿ....0`Þ.......|
>00030: 00 00 00 00 00 A0 0F 3F 00 00 00 00 00 A0 0F |..... .?..... . |
>
>main: writeWireFormat
>00000: FF 53 4D 42 2F 00 00 00 00 18 03 80 00 00 00 00 |ÿSMB/...........|
>00010: 00 00 00 00 00 00 00 00 00 08 6B 12 00 08 DF 16 |..........k...ß.|
>00020: 0E FF 00 00 00 07 30 60 DE 02 00 00 00 00 00 00 |.ÿ....0`Þ.......|
>00030: 00 00 00 00 00 A0 0F 3F 00 00 00 00 00 A0 0F |..... .?..... . |
>
>main:
>SmbComWriteAndX[command=SMB_COM_WRITE_ANDX,received=false,errorCode=0x00000000,flags=0x0018,flags2=0x8003,tid=2048,pid=4715,uid=2048,mid=5855,wordCount=14,byteCount=4000,andxCommand=0xFF,andxOffset=0,fid=12295,offset=188000,writeMode=0,remaining=0,dataLength=4000,dataOffset=63]
>00000: FF 53 4D 42 2F 00 00 00 00 18 03 80 00 00 00 00 |ÿSMB/...........|
>00010: 00 00 00 00 00 00 00 00 00 08 6B 12 00 08 DF 16 |..........k...ß.|
>00020: 0E FF 00 00 00 07 30 60 DE 02 00 00 00 00 00 00 |.ÿ....0`Þ.......|
>00030: 00 00 00 00 00 A0 0F 3F 00 00 00 00 00 A0 0F |..... .?..... . |
>
>So each sub-encoding method is called first and then the full SMB toString
>and it's hexdump is printed immediately after the packet is written to the
>wire. So this last dump is what should appear on the wire. Also notice the
>thread name preceeds every debugging message (in the above case it is
>'main').
>
>The data shown is just the header so the third line will always look like
>this (not to be confused with other packets that will likey have a
>different
>WordCount other than 0E):
>
>00020: 0E FF 00 00 00 07 30 60 DE 02 00 00 00 00 00 00 |.ÿ....0`Þ.......|
> 1 2 3 4 5 6 7
>
>The fields are:
>
>1 WordCount
>2 AndXCommand
>3 AndXReserved
>4 AndXOffset
>5 Fid
>6 Offset <---- HERE'S THE OFFSET FIELD
>7 Reserved
>
>So you should be able to just eyeball that 1st byte of the Offset (0x60
>depicted above) and zero in on where it get's clobbered to 0x00. Can
>you do that?
>
>Also you might try this jar:
>
> http://home.comcast.net/~miallen1/jcifs/jcifs-0.9.0p3.jar
>
>It has some very significant changes regarding how the NbtSocket layer
>works and how MIDs (multiplex ids) are allocated. It's basically a
>"cleanup release" so it's very much a work in progress but it's reported
>to work well so far. Probably won't make a difference but it's worth a
>shot.
>
>
>
>>There seems so little time/space for this to go wrong!
>>Could the signing be going wrong - don't think so - we don't think we
>>are using this and, anyway it would do an arraycopy of 8 bytes
>>
>>
>
>Doubt it's signing.
>
>
>
>>writeWireFormat just calls writeHeader and writeAndXWireFormat which
>>seem simple enough...
>>
>>
>
>Right. If toString says offset is right (4000) but the hexdump printed
>after the packet is written to the wire is wrong than let's see if we can
>zoom in on what in between is causing that byte to get clobbered.
>
>
>
>>there does not seem to be batching going on...
>>
>>
>
>I've never seen anything batch with an SmbComWriteAndX. You can set
>jcifs.smb.client.useBatching = false.
>
>This is kind of a serious bug so I hope we can figure it out. I just
>wish I could reproduce it. It's going to be tough without a minimalistic
>program to reproduce the issue.
>
>Mike
>
>
>
>
-------------- next part --------------
HTML attachment scrubbed and removed
More information about the jcifs
mailing list