ValueError('Unexpected binary attachment') on Client

[bhakta0007]

Hello,

I am using socketio sync client with Flask-socketio server. I am hitting this exception "Unexpected binary attachment" every once in a few hours of operation. The client(s) and server are constantly communicating during this time. The rate of messages is < 50 messages per second from servers standpoint.

I use Flask-socketio as a hub. Clients connect to the server, and the server (hub) allows clients to talk to each other (via message header that has src/dst for routing). In this case the client is in the process of communicating with multiple other client(s), with server being the relay. The client communicates with other client(s) in a serial fashion (there are no parallel requests made at the same time.

Versions

client:

(venv) ~/dev/at$ pip freeze | grep -i socket
python-socketio==4.2.0
websocket-client==0.57.0
(venv) ~/dev/at$ pip freeze | grep -i engine
python-engineio==3.8.2.post1

server

(venv) bhakta@server:~/dev/controller$ pip freeze | grep -i engine
python-engineio==3.10.0
(venv) bhakta@server:~/dev/controller$ pip freeze | grep -i socket
Flask-SocketIO==4.2.1
python-socketio==4.3.1
socketIO-client==0.7.2
websocket-client==0.56.0

The client hangs up on this exception.

Exception in thread Thread-250165:
Traceback (most recent call last):
  File "/usr/lib64/python3.6/threading.py", line 916, in _bootstrap_inner
    self.run()
  File "/usr/lib64/python3.6/threading.py", line 864, in run
    self._target(*self._args, **self._kwargs)
  File "/home/bhakta/dev/at/venv/lib/python3.6/site-packages/socketio/client.py", line 552, in _handle_eio_message
    if pkt.add_attachment(data):
  File "/home/bhakta/dev/at/venv/lib/python3.6/site-packages/socketio/packet.py", line 118, in add_attachment
    raise ValueError('Unexpected binary attachment')
ValueError: Unexpected binary attachment

I event put a pdb at the Value error place to inspect the conditions

(Pdb) self.attachment_count
1
(Pdb) self.attachments
[b'PING 192.168.90.2 (192.168.90.2) 56(84) bytes of data.\n64 bytes from 192.168.90.2: icmp_seq=1 ttl=64 time=30.0 ms\n64 bytes from 192.168.90.2: icmp_seq=2 ttl=64 time=30.1 ms\n64 bytes from 192.168.90.2: icmp_seq=3 ttl=64 time=30.1 ms\n64 bytes from 192.168.90.2: icmp_seq=4 ttl=64 time=30.0 ms\n64 bytes from 192.168.90.2: icmp_seq=5 ttl=64 time=30.0 ms\n64 bytes from 192.168.90.2: icmp_seq=6 ttl=64 time=30.0 ms\n64 bytes from 192.168.90.2: icmp_seq=7 ttl=64 time=30.0 ms\n64 bytes from 192.168.90.2: icmp_seq=8 ttl=64 time=30.1 ms\n64 bytes from 192.168.90.2: icmp_seq=9 ttl=64 time=30.0 ms\n64 bytes from 192.168.90.2: icmp_seq=10 ttl=64 time=30.0 ms\n\n--- 192.168.90.2 ping statistics ---\n10 packets transmitted, 10 received, 0% packet loss, time 45033ms\nrtt min/avg/max/mdev = 30.050/30.079/30.148/0.113 ms\n']
(Pdb)

I have searched for this error without any luck for previous instances . I need some help to figure what is happening.

More importantly, I am concerned that this exception hangs the client and there is no way to recover than press Ctrl-C and restart the client. I would have liked it if the message was discarded (so application can re-try).

1. Any clues on what might be happening? I am willing to provide any additional information you might need. I am able to consistently reproduce the problem every few hours
2. Am I using the right set of package versions?
3. Is there a way to avoid the exception so application can proceed? The current behavior of the thread exception hangs the app.

[miguelgrinberg]

Is your client multithreaded?

The problem is that an emit operation with attachments is not atomic, it requires several network writes. If two threads are emitting at about the same time their writes can get mixed up.

[bhakta0007]

Yes, I have a scenario where I spawn multiple threads in the client, each to talk to one of the N other hosts.

Is the mixing up only an issue in the write-path? Does it also affect the RX path?

How should I deal with this. Should I have a lock around socketio operations so only one thread is using the socketio at a time?

How can we gracefully deal with this error? I already have logic in the client app to re-try on failures, but the exception is throwing the whole app out.

[miguelgrinberg]

This is only a problem if your application issues writes from different threads at the same time. It is not a problem for incoming events.

The easiest way to deal with this is to create a critical section around the emit, so that only one emit gets to run at a given time. You can use a Lock object for this.

[bhakta0007]

I have incorporated this change, I will run my tests for the next 48 hours and update this thread with my findings

[bhakta0007]

@miguelgrinberg

The content I saw from the pdb when the problem occured, is actually what I receive (and not what I transmit). Would you still think the problem is related to the transmit path?

(Pdb) self.attachment_count
1
(Pdb) self.attachments
[b'PING 192.168.90.2 (192.168.90.2) 56(84) bytes of data.\n64 bytes from 192.168.90.2: icmp_seq=1 ttl=64 time=30.0 ms\n64 bytes from 192.168.90.2: icmp_seq=2 ttl=64 time=30.1 ms\n64 bytes from 192.168.90.2: icmp_seq=3 ttl=64 time=30.1 ms\n64 bytes from 192.168.90.2: icmp_seq=4 ttl=64 time=30.0 ms\n64 bytes from 192.168.90.2: icmp_seq=5 ttl=64 time=30.0 ms\n64 bytes from 192.168.90.2: icmp_seq=6 ttl=64 time=30.0 ms\n64 bytes from 192.168.90.2: icmp_seq=7 ttl=64 time=30.0 ms\n64 bytes from 192.168.90.2: icmp_seq=8 ttl=64 time=30.1 ms\n64 bytes from 192.168.90.2: icmp_seq=9 ttl=64 time=30.0 ms\n64 bytes from 192.168.90.2: icmp_seq=10 ttl=64 time=30.0 ms\n\n--- 192.168.90.2 ping statistics ---\n10 packets transmitted, 10 received, 0% packet loss, time 45033ms\nrtt min/avg/max/mdev = 30.050/30.079/30.148/0.113 ms\n']
(Pdb)

[bhakta0007]

I still see the issue after guarding emit with a Lock. Like I mentioned in my previous message, the contents of the attachments again points to the receive path payload.

[miguelgrinberg]

Yes, this suggests you have multiple emits running concurrently actually. What did you do with the lock? Can I review this change? Maybe I was incorrect in claiming that a lock would be enough, I'll review on my side as well.

[bhakta0007]

I am going to pull out the relevant pieces of code and try and create a stand-alone example. Let me see if I can recreate the issue with the stand-alone code. Will attempt this over the weekend.

[bhakta0007]

I created a sio_send function that is called by any function that wants to send a mesage. I have replaced all occurrences of sio.emit with sio_send

sendLock = threading.Lock()
def sio_send(data, msgType="message"):
    sendLock.acquire()
    try:
        sio.emit(msgType, data)
    except Exception as ec:
        logger.error("sio_send: Error sending msg - {}".format(ec))
    sendLock.release()

[miguelgrinberg]

I reviewed the code and I don't really see how the packets can get mixed up if the emits are never running at the same time. Any chance you can create a small example application that I can use to test and reproduce this behavior?

[bhakta0007]

Thanks Miguel, for checking the code.

I have tried to extract the code to create a minimal example but that has't helped reproduce the issue.

I am currently working on trying to create an example where the problem can be reproduced. I will post back to this thread once I have a failing-example.