[ZODB-Dev] Problem with large transactions combined with authentication mode

Tue Dec 16 15:24:01 EST 2003

On Sat, Nov 29, 2003 at 02:09:42PM +0100, Per Sigmond wrote:
> I can provoke the error (consistent) with the client code below. Turning off 
> authentication makes the error go away. The failure happens on different 
> messages every time, the failing 'load key' in the server error message is 
> random, or so it seems.

I've done some tcpdumping to locate where we're choking. Roughly, the
initial exchange that precedes the error is:

    0. ... ZEO Client/Server setup, including successful auth negotiation

    1. Client calls server zeoLoad(); server answers

    2. Client calls server tpc_begin(); server answers

    3. Client calls server new_oids(); server acks

    4. Server sends back set of oids in three separate TCP packets
       (probably broken at Ethernet frame size).

At this point, the client chokes while decoding the start of message
containing the OIDs, and disconnects from the storage (I see the FINs
coming over the wire after the new_oids() call has returned all that's
coming). Here's the raw data:

Step 3 (client requests new_oids()):

   0040        80 00 00 17 bf 85  63 d1 d5 81 45 2b 27 4b     ....¿. cÑÕ.E+'K
   0050  3f a0 03 2b 65 2f 93 4c  58 38 28 49 38 0a 49 30   ? .+e/.L X8(I8.I0
   0060  0a 53 27 6e 65 77 5f 6f  69 64 73 27 0a 28 74 74   .S'new_o ids'.(tt
   0070  2e                                                 .                

Step 4 (server answer with oids):

   0040        80 00 0e 83 b1 18  18 a2 e3 8f 18 10 70 1e     ....±. .¢ã...p.
   0050  e6 0e 91 fc 83 93 e4 36  a8 70 28 49 38 0a 49 30   æ..ü..ä6 ¨p(I8.I0
   0060  0a 53 27 2e 72 65 70 6c  79 27 0a 28 6c 53 27 5c   .S'.repl y'.(lS'\
   0070  78 30 30 5c 78 30 30 5c  78 30 30 5c 78 30 30 5c   x00\x00\ x00\x00\

   (Goes on for another 1300 bytes or so) 

The client chokes here and complains that it 'can't decode message: 

    "\xb1\x18\x18\xa2\xe3\x8f\x18\x1 0p\x1e\xe6\x0e\x91\xfc\x..."'

Which matches the OIDs coming back from the server in step 4. Now the
funny part about that is that it *seems* the client is trying to decode
the zrpc header -- it should start decoding after the quotes open (IOW,
the string starting with '\x00...'). 

Now I'm not on top of how the header calculations are done inside
smac.py, so I'll drop of here slightly happier that I've tracked
*something* down. At this point I request help from above <wink>!

However, apart from the error, I'm confused here by one thing in your
message:

> 2003-11-29T14:02:30 ERROR(200) zrpc:4398 can't decode message: 
> '{<a\x85tP\xfa\xbe\x17\x84\x08\xa5[V[\xb1(\x0b\x05\xac(K...'
> ------
> 2003-11-29T14:02:30 ERROR(200) zrpc-conn:127.0.0.1:33068 Error caught in 
> asyncore
> Traceback (most recent call last):
>   File 
> "/home/per/zodb/ZODB3-3.2/build/lib.linux-i686-2.2/ThreadedAsync/LoopCallback.py", 
> line 120, in poll
>     obj.handle_read_event()
>   File "/usr/lib/python2.2/asyncore.py", line 397, in handle_read_event
>     self.handle_read()
>   File "/home/per/zodb/ZODB3-3.2/build/lib.linux-i686-2.2/ZEO/zrpc/smac.py", 
> line 211, in handle_read
>     self.message_input(msg)
>   File 
> "/home/per/zodb/ZODB3-3.2/build/lib.linux-i686-2.2/ZEO/zrpc/connection.py", 
> line 230, in message_input
>     msgid, flags, name, args = self.marshal.decode(message)
>   File 
> "/home/per/zodb/ZODB3-3.2/build/lib.linux-i686-2.2/ZEO/zrpc/marshal.py", line 
> 39, in decode
>     return unpickler.load() # msgid, flags, name, args
> UnpicklingError: invalid load key, '{'.
> ------
> 2003-11-29T14:02:30 INFO(0) ZSS:4398/127.0.0.1:33068 disconnected during 
> transaction Transaction user=''
> 
> 
> 
> Error on the client:
> Traceback (most recent call last):
>   File "bigtransbug.py", line 20, in ?
>     get_transaction().commit()
>   File 
> "/home/per/zodb/ZODB3-3.2/build/lib.linux-i686-2.2/ZODB/Transaction.py", line 
> 244, in commit
>     vote(self)
>   File "/home/per/zodb/ZODB3-3.2/build/lib.linux-i686-2.2/ZODB/Connection.py", 
> line 698, in tpc_vote
>     s = vote(transaction)
>   File 
> "/home/per/zodb/ZODB3-3.2/build/lib.linux-i686-2.2/ZEO/ClientStorage.py", 
> line 833, in tpc_vote
>     self._server.vote(self._serial)
>   File "/home/per/zodb/ZODB3-3.2/build/lib.linux-i686-2.2/ZEO/ServerStub.py", 
> line 91, in vote
>     return self.rpc.call('vote', trans_id)
>   File 
> "/home/per/zodb/ZODB3-3.2/build/lib.linux-i686-2.2/ZEO/zrpc/connection.py", 
> line 367, in call
>     r_flags, r_args = self.wait(msgid)
>   File 
> "/home/per/zodb/ZODB3-3.2/build/lib.linux-i686-2.2/ZEO/zrpc/connection.py", 
> line 457, in wait
>     raise DisconnectedError()
> ZEO.zrpc.error.DisconnectedError

I am convinced I'm seeing this error on the client, which is choking on
what new_oids() is returning to it -- the server *generates* the bits
it's failing to decode, right?

Or am I utterly mistaken?

Take care,
--
Christian Robottom Reis | http://async.com.br/~kiko/ | [+55 16] 261 2331