Unexpected Packet

[oldarmyc]

Trying to use this in order to interact with xenbus on a guest VM but keep running into an issue where I get the following:

UnexpectedPacket: _Packet(op=2, rq_id=66813, tx_id=0, size=360, payload='{}')

The code I am running is pretty straight forward as I am just trying to read the networking info from a particular mac address.

from pyxs.client import Router, Client
from pyxs.connection import XenBusConnection
router = Router(XenBusConnection())

with Client(router=router) as c:
    try:
        networking = c[b"vm-data/networking/BC764E20394F"]
        print(networking)
    except:
        pass

Is there something that I need to set that I am missing, or is it that this can only be run on the underlying host and not the guest vm.

[superbobry]

Hi Dave, thanks for reporting this. Could you add full stack trace to the issue?

[oldarmyc]

Exception in thread Thread-1:
Traceback (most recent call last):
  File "/usr/lib64/python2.7/threading.py", line 804, in __bootstrap_inner
    self.run()
  File "/usr/lib64/python2.7/threading.py", line 757, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/lib/python2.7/site-packages/pyxs/client.py", line 118, in __call__
    raise UnexpectedPacket(packet)
UnexpectedPacket: _Packet(op=2, rq_id=66813, tx_id=0, size=360, payload='{}')

[superbobry]

pyxs was designed to be usable from both dom0 and the guest VMs. However, it's been a while since I tested it in the guest, since it's somewhat more cumbersome to do in VirtualBox :)

The error you're seeing is due to the Packet.rq_id field mismatch. If the above stacktrace is for the first request in the session, then the request was sent with rq_id=0 (you could check the last value in pyxs._internal._rq_id) and Client expects a reply with the same rq_id=0. Instead it gets a packet with rq_id= 66813, which corresponds to a request never issued by pyxs, therefore the error.

I remember seeing something like this a few years ago, but I can't recall the details. You could try simply logging all unexpected packets instead of raising an exception. Maybe XenStore actually issues another packet with correct rq_id right after that one.

Sadly, this is all I could help with for now. I would very much appreciate if you could find the time to pinpoint this, because I don't have a Xen machine at hand at the moment, and can't debug this easily.

[oldarmyc]

So I added some print statements and it does look like it gets executed twice

[root@dtk-dev-server ~]# python test_router.py
client.py - __call__ while: Start of true loop
 client.py - execute_command - kwargs rq_id: 0
_internal.py - __new__: 0
client.py - send - Request ID: 0
connection.py - send - Request ID: 0
connection.py - XBTransport.send:
connection.py - XBTransport.send: vm-data/networking/BC764E20394F
client.py - execute : after send on router
_internal.py - __new__: 87652
Exception in thread Thread-1:
Traceback (most recent call last):
  File "/usr/lib64/python2.7/threading.py", line 804, in __bootstrap_inner
    self.run()
  File "/usr/lib64/python2.7/threading.py", line 757, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/lib/python2.7/site-packages/pyxs/client.py", line 119, in __call__
    raise UnexpectedPacket(packet)
UnexpectedPacket: _Packet(op=2, rq_id=87652, tx_id=0, size=360, payload='{}')

It looks like the send is being done twice here as reflected in the following:
https://github.com/selectel/pyxs/blob/master/pyxs/connection.py#L85

It sends the header then makes the request and on the second send the request_id changes.

[superbobry]

IIRC each request consists of a header and a payload, therefore the client sends a single request and, from what I see in your log, gets a single request back with incorrect rq_id:

client.py - execute : after send on router
_internal.py - __new__: 87652

[oldarmyc]

Here is better output.

client.py - __call__ while: Start of true loop
 client.py - execute_command - kwargs rq_id: 0
_internal.py - __new__: 0
client.py - send - Request ID: 0
connection.py - send - _Packet(op=2, rq_id=0, tx_id=0, size=32, payload='vm-data/networking/BC764E20394F\x00')
connection.py - send - Request ID: 0
connection.py - sending header:
connection.py - XBTransport.send:
connection.py - sending payload: _Packet(op=2, rq_id=0, tx_id=0, size=32, payload='vm-data/networking/BC764E20394F\x00')
connection.py - XBTransport.send: vm-data/networking/BC764E20394F
client.py - execute : after send on router
connection.py - recv - �h
connection.py - receive: �h
connection.py - receive variables
op: 2
rq_id: 583908
tx_id: 0
size: 360
End of receive variables
connection.py - recv - {SCRUBBED_DATA}
_internal.py - __new__: 583908
client - __call__ - 583908:
client - __call__ - {0: RVar(None)}:
client - __call__ - None:
Exception in thread Thread-1:
Traceback (most recent call last):
  File "/usr/lib64/python2.7/threading.py", line 804, in __bootstrap_inner
    self.run()
  File "/usr/lib64/python2.7/threading.py", line 757, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/lib/python2.7/site-packages/pyxs/client.py", line 126, in __call__
    raise UnexpectedPacket(packet)

You can see here that the request ID is sent correctly but the receive gets a new Request ID that does not match.

Is this due to this being executed on a guest instance and not on the host itself?
With this being on a guest instance is the request ID verification needed?

[superbobry]

XenStore spec doesn't mention any exceptions for guest mode and XenStore client used by device drivers indeed returns an error in this case. The reason for that is that you receive a response for an unknown request, you can't do anything with it -- it's just noise.

Could you try ignoring unmatched packets just to see if XenStore would send anything else after that?

[oldarmyc]

I did and the script just hangs waiting as the wait never gets told to stop that is in the RVar class get

with self.condition:
    while self.target is None:
        _condition_wait(self.condition)

[superbobry]

Yep, this means that XenStore indeed echoes the wrong rq_id back. Which version of Xen / xenstored are you running?

[oldarmyc]

Underlying hosts are both running Xen 6.2.

On the guest instances the same thing happens with both versions below:
xe-guest-utilities-xenstore-6.2.0-1120.x86_64
xe-guest-utilities-xenstore-7.0.0-24.x86_64

[superbobry]

Thank you, sadly I wasn't able to find anything in the mailing list.

Could you try to access the same path using official Python APis (libxs bindings); and using a Unix socket transport (I think it is available on the guests as well)?

[oldarmyc]

I built two servers on the same Xen hypervisor which is running XenServer 6.2 and both guests running the same version of xenstore (xe-guest-utilities-xenstore-6.2.0-1120.x86_64)

The first guest is a RHEL 7 instance and the second is a Fedora 24 (also tried F25 and F26) instance.

Both scripts are exactly the same running the following code:

from pyxs.client import Router
from pyxs.connection import XenBusConnection
from pyxs.client import Client


XENBUS_ROUTER = Router(XenBusConnection())
with Client(router=XENBUS_ROUTER) as client:
    mac_addrs = []
    for item in client.list(b'vm-data/networking'):
        mac_addrs.append(item.decode('utf-8').strip())

    print(mac_addrs)

On RHEL 7 running python 2 or python 3 the script succeeds and prints the mac addresses as expected.

[root@test-rh7 ~]# python testing_pyxs.py
[u'BC764E201467', u'BC764E201102']

[root@test-rh7 ~]# python3 testing_pyxs.py
['BC764E201467', 'BC764E201102']

On Fedora 24 using python 2 or python 3 produces the UnexpectedPacket exception as follows.

[root@test-f24 ~]# python testing_pyxs.py
Exception in thread Thread-1:
Traceback (most recent call last):
  File "/usr/lib64/python2.7/threading.py", line 804, in __bootstrap_inner
    self.run()
  File "/usr/lib64/python2.7/threading.py", line 757, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/lib/python2.7/site-packages/pyxs/client.py", line 118, in __call__
    raise UnexpectedPacket(packet)
UnexpectedPacket: _Packet(op=1, rq_id=35256, tx_id=0, size=26, payload='BC764E207F35\x00BC764E207F31\x00')

[root@test-f24 ~]# python3 testing_pyxs.py
Exception in thread Thread-1:
Traceback (most recent call last):
  File "/usr/lib64/python3.5/threading.py", line 914, in _bootstrap_inner
    self.run()
  File "/usr/lib64/python3.5/threading.py", line 862, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.5/site-packages/pyxs/client.py", line 118, in __call__
    raise UnexpectedPacket(packet)
pyxs.exceptions.UnexpectedPacket: Packet(op=1, rq_id=35294, tx_id=0, size=26, payload=b'BC764E207F35\x00BC764E207F31\x00')

The UnexpectedPacket exception also happens in CentOS as well. Not sure what is different between RHEL 7 and the other operating systems as when running the same version of tools on the same hypervisor produces the results as detailed above.