Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Sending buffer bug after network fail #6

Open
uint69-t opened this issue Jan 28, 2023 · 7 comments
Open

Sending buffer bug after network fail #6

uint69-t opened this issue Jan 28, 2023 · 7 comments

Comments

@uint69-t
Copy link

uint69-t commented Jan 28, 2023 •
edited
Loading

Hey, very cool project! Today i was testing the code in a long run, and this happend:

[DEBUG ] [MainThread] [2023-01-28 03:57:24,939 ] try to communicate addr=('192.168.0.30', 50001) bind=['', 50001]
[DEBUG ] [MainThread] [2023-01-28 03:57:24,940 ] select curve NIST256p (static)
[DEBUG ] [MainThread] [2023-01-28 03:57:25,234 ] success getting shared key
[DEBUG ] [MainThread] [2023-01-28 03:57:25,250 ] success hand shaking
[DEBUG ] [MainThread] [2023-01-28 03:57:25,498 ] success get MUT size 1472b
[DEBUG ] [MainThread] [2023-01-28 03:57:25,500 ] connect success! mtu=1472
[DEBUG ] [Thread-2  ] [2023-01-28 03:57:25,523 ] send operation success 4110b
[DEBUG ] [Thread-2  ] [2023-01-28 03:57:25,524 ] send now! loss=0 time=1674878245
[DEBUG ] [SRUDP     ] [2023-01-28 03:57:25,528 ] reached end of chunk seq=3
[DEBUG ] [SRUDP     ] [2023-01-28 03:57:25,532 ] allow sending operation again seq=3
[DEBUG ] [Thread-1  ] [2023-01-28 03:57:25,563 ] received! 4110b loss=0 79.25kb/s

[DEBUG ] [SRUDP     ] [2023-01-28 03:57:45,519 ] reached end of chunk seq=6
[DEBUG ] [Thread-2  ] [2023-01-28 03:57:45,558 ] send operation success 4110b
[DEBUG ] [Thread-2  ] [2023-01-28 03:57:45,559 ] send now! loss=0 time=1674878265
[DEBUG ] [Thread-2  ] [2023-01-28 03:57:45,562 ] send broadcast!
[DEBUG ] [Thread-1  ] [2023-01-28 03:57:45,564 ] received! 4110b loss=0 75.75kb/s

[DEBUG ] [SRUDP     ] [2023-01-28 03:57:45,567 ] allow sending operation again seq=6
[DEBUG ] [SRUDP     ] [2023-01-28 03:58:05,523 ] reached end of chunk seq=9
[DEBUG ] [SRUDP     ] [2023-01-28 03:58:05,526 ] find you!!! (Packet(BCT seq:0 retry:0 time:1674878285.51 data:27b))
[DEBUG ] [Thread-1  ] [2023-01-28 03:58:05,563 ] received! 4110b loss=0 83.46kb/s

[DEBUG ] [Thread-2  ] [2023-01-28 03:58:05,596 ] send operation success 4110b
[DEBUG ] [Thread-2  ] [2023-01-28 03:58:05,596 ] send now! loss=0 time=1674878285
[DEBUG ] [Thread-2  ] [2023-01-28 03:58:05,599 ] send broadcast!
[DEBUG ] [SRUDP     ] [2023-01-28 03:58:05,603 ] allow sending operation again seq=9
Exception in thread SRUDP:
Traceback (most recent call last):
  File "/usr/lib/python3.9/threading.py", line 954, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.9/threading.py", line 892, in run
    self._target(*self._args, **self._kwargs)
  File "/home/pi/srudp/srudp/__init__.py", line 449, in _backend
    self.sendto(self._encrypt(packet2bin(p)), self.address)
  File "/home/pi/srudp/srudp/__init__.py", line 667, in sendto
    return self.receiver_socket.sendto(data, address)
OSError: [Errno 101] Network is unreachable
[DEBUG ] [Thread-2  ] [2023-01-28 03:58:25,631 ] send operation success 4110b
[DEBUG ] [Thread-2  ] [2023-01-28 03:58:25,632 ] send now! loss=0 time=1674878305
[DEBUG ] [Thread-2  ] [2023-01-28 03:58:45,664 ] send operation success 4110b
[DEBUG ] [Thread-2  ] [2023-01-28 03:58:45,664 ] send now! loss=0 time=1674878325
[DEBUG ] [Thread-2  ] [2023-01-28 03:59:05,696 ] send operation success 4110b
[DEBUG ] [Thread-2  ] [2023-01-28 03:59:05,697 ] send now! loss=0 time=1674878345
[DEBUG ] [Thread-2  ] [2023-01-28 03:59:25,729 ] send operation success 4110b
[DEBUG ] [Thread-2  ] [2023-01-28 03:59:25,730 ] send now! loss=0 time=1674878365
[DEBUG ] [Thread-2  ] [2023-01-28 03:59:45,762 ] send operation success 4110b
[DEBUG ] [Thread-2  ] [2023-01-28 03:59:45,762 ] send now! loss=0 time=1674878385
[DEBUG ] [Thread-2  ] [2023-01-28 04:00:05,795 ] send operation success 4110b
[DEBUG ] [Thread-2  ] [2023-01-28 04:00:05,795 ] send now! loss=0 time=1674878405
[DEBUG ] [Thread-2  ] [2023-01-28 04:00:25,827 ] send operation success 4110b
[DEBUG ] [Thread-2  ] [2023-01-28 04:00:25,828 ] send now! loss=0 time=1674878425
[DEBUG ] [Thread-2  ] [2023-01-28 04:00:25,831 ] send broadcast!
[DEBUG ] [Thread-2  ] [2023-01-28 04:00:45,863 ] send operation success 4110b
[DEBUG ] [Thread-2  ] [2023-01-28 04:00:45,864 ] send now! loss=0 time=1674878445
[DEBUG ] [Thread-2  ] [2023-01-28 04:01:05,906 ] send operation success 4110b
[DEBUG ] [Thread-2  ] [2023-01-28 04:01:05,907 ] send now! loss=0 time=1674878465
[DEBUG ] [Thread-2  ] [2023-01-28 04:01:25,939 ] send operation success 4110b
[DEBUG ] [Thread-2  ] [2023-01-28 04:01:25,940 ] send now! loss=0 time=1674878485
[DEBUG ] [Thread-2  ] [2023-01-28 04:01:25,943 ] send broadcast!

The "Network is unreachable" it is intentional, i was testing how the code would behave in the case of that happening.
But the wired thing comes after:

[DEBUG ] [Thread-2  ] [2023-01-28 04:17:47,605 ] send now! loss=0 time=1674879467
[DEBUG ] [Thread-2  ] [2023-01-28 04:17:47,608 ] send broadcast!
[DEBUG ] [Thread-2  ] [2023-01-28 04:18:07,641 ] send operation success 4110b
[DEBUG ] [Thread-2  ] [2023-01-28 04:18:07,642 ] send now! loss=0 time=1674879487
[DEBUG ] [Thread-2  ] [2023-01-28 04:18:07,645 ] send broadcast!
[DEBUG ] [Thread-2  ] [2023-01-28 04:18:27,678 ] send operation success 4110b
[DEBUG ] [Thread-2  ] [2023-01-28 04:18:27,679 ] send now! loss=0 time=1674879507
[DEBUG ] [Thread-2  ] [2023-01-28 04:18:47,713 ] send operation success 4110b
[DEBUG ] [Thread-2  ] [2023-01-28 04:18:47,713 ] send now! loss=0 time=1674879527
[DEBUG ] [Thread-2  ] [2023-01-28 04:19:07,747 ] send operation success 4110b
[DEBUG ] [Thread-2  ] [2023-01-28 04:19:07,748 ] send now! loss=0 time=1674879547
[DEBUG ] [Thread-2  ] [2023-01-28 04:19:27,781 ] send operation success 4110b
[DEBUG ] [Thread-2  ] [2023-01-28 04:19:27,782 ] send now! loss=0 time=1674879567
[DEBUG ] [Thread-2  ] [2023-01-28 04:19:47,808 ] buffer is full and wait for signaled
[DEBUG ] [Thread-2  ] [2023-01-28 04:20:08,810 ] waiting for sending buffer have space..
[DEBUG ] [Thread-2  ] [2023-01-28 04:20:29,811 ] waiting for sending buffer have space..
[DEBUG ] [Thread-2  ] [2023-01-28 04:20:50,813 ] waiting for sending buffer have space..
[DEBUG ] [Thread-2  ] [2023-01-28 04:21:11,814 ] waiting for sending buffer have space..
[DEBUG ] [Thread-2  ] [2023-01-28 04:21:32,816 ] waiting for sending buffer have space..
[DEBUG ] [Thread-2  ] [2023-01-28 04:21:53,817 ] waiting for sending buffer have space..
[DEBUG ] [Thread-2  ] [2023-01-28 04:22:14,819 ] waiting for sending buffer have space..
[DEBUG ] [Thread-2  ] [2023-01-28 04:22:35,820 ] waiting for sending buffer have space..
[DEBUG ] [Thread-2  ] [2023-01-28 04:22:56,822 ] waiting for sending buffer have space..
[DEBUG ] [Thread-2  ] [2023-01-28 04:23:17,823 ] waiting for sending buffer have space..
[DEBUG ] [Thread-2  ] [2023-01-28 04:23:38,825 ] waiting for sending buffer have space..
[DEBUG ] [Thread-2  ] [2023-01-28 04:23:59,826 ] waiting for sending buffer have space..
[DEBUG ] [Thread-2  ] [2023-01-28 04:24:20,827 ] waiting for sending buffer have space..
[DEBUG ] [Thread-2  ] [2023-01-28 04:24:41,829 ] waiting for sending buffer have space..
[DEBUG ] [Thread-2  ] [2023-01-28 04:25:02,830 ] waiting for sending buffer have space..
[DEBUG ] [Thread-2  ] [2023-01-28 04:25:23,832 ] waiting for sending buffer have space..
[DEBUG ] [Thread-2  ] [2023-01-28 04:25:44,833 ] waiting for sending buffer have space..
[DEBUG ] [Thread-2  ] [2023-01-28 04:26:05,835 ] waiting for sending buffer have space..
[DEBUG ] [Thread-2  ] [2023-01-28 04:26:26,836 ] waiting for sending buffer have space..
(...)

Something wierd happend in the middle and i cant figure what, any idea?
Again, very good project, very good code structure, i will upload some PRs to contribute.

~ uint69_t
@uint69-t uint69-t changed the title Sending buffer buffer bug after network fail Sending buffer bug after network fail Jan 28, 2023
@namuyan
Copy link
Owner

namuyan commented Jan 29, 2023 •
edited
Loading

Thank you for comment!

The problem is looks simple, the UDP socket is flagged "broken" by OS.
I don't know why because I'm not you, I don't know your system env (not occur on my env, declare!).
I just estimate, the program use receiver_socket.sendto() too often and force closed (just packet loss on my env)
, or receiver_socket.sendto() method used by another thread and broken.

I think two solution.
1, regenerate socket object if receiver_socket is broken (feel not good)
2, add wait FULL_SIZE_PACKET_WAIT, but blocking send method is not good (feel bad)
3, lock the socket when using (feel not so good)

First of all, you should write down you env and check OS logs you can.

I also need to fix, exception on sendall() by checking self.is_closed.

@uint69-t
Copy link
Author

Sorry, i forgot. [Linux 5.15.0-58-generic][Linux Mint 20.04][x86_64]

I think the best option is to lock the socket, since we are dealing with communication with ACK packets, I think it would be the most "standard" idea.

@uint69-t
Copy link
Author

Also, i wrote a small test to check for this behavior:

CODE SIDE A:

    sock.connect((remote_host, port))
    log.debug("connect success! mtu=%d", sock.mtu_size)

    sock.sendall("HELLO".encode())
    while not sock.is_closed:
        print(sock.recv(16).decode())

CODE SIDE B:

    sock.connect((remote_host, port))
    log.debug("connect success! mtu=%d", sock.mtu_size)

    if sock.recv(5).decode() == "HELLO":
        while not sock.is_closed:
            sock.sendall(str(time()).encode())

OUTPUT SIDE A:

[DEBUG ] [MainThread] [2023-01-29 17:40:14,383 ] try to communicate addr=('192.168.0.30', 50001) bind=['', 50001]
[DEBUG ] [MainThread] [2023-01-29 17:40:14,386 ] success establishing connection
[DEBUG ] [MainThread] [2023-01-29 17:40:14,542 ] success get MUT size 1472b
[DEBUG ] [MainThread] [2023-01-29 17:40:14,544 ] connect success! mtu=1472
[DEBUG ] [MainThread] [2023-01-29 17:40:14,545 ] send operation success 5b
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,548 ] allow sending operation again seq=1
1675014014.55271
82
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,550 ] reached end of chunk seq=1
1675014014.55307
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,552 ] reached end of chunk seq=2
82
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,554 ] reached end of chunk seq=3
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,556 ] reached end of chunk seq=4
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,557 ] reached end of chunk seq=5
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,559 ] reached end of chunk seq=6
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,561 ] reached end of chunk seq=7
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,562 ] reached end of chunk seq=8
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,563 ] reached end of chunk seq=9
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,565 ] reached end of chunk seq=10
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,566 ] reached end of chunk seq=11
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,567 ] reached end of chunk seq=12
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,568 ] reached end of chunk seq=13
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,569 ] reached end of chunk seq=14
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,571 ] reached end of chunk seq=15
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,572 ] reached end of chunk seq=16
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,574 ] reached end of chunk seq=17
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,576 ] reached end of chunk seq=18
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,577 ] reached end of chunk seq=19
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,578 ] reached end of chunk seq=20
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,580 ] reached end of chunk seq=21
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,582 ] reached end of chunk seq=22
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,584 ] reached end of chunk seq=23
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,585 ] reached end of chunk seq=24
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,586 ] reached end of chunk seq=25
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,587 ] reached end of chunk seq=26
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,588 ] reached end of chunk seq=27
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,589 ] reached end of chunk seq=28
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,590 ] reached end of chunk seq=29
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,592 ] reached end of chunk seq=30
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,594 ] reached end of chunk seq=31
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,595 ] reached end of chunk seq=32
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,596 ] reached end of chunk seq=33
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,597 ] reached end of chunk seq=34
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,598 ] reached end of chunk seq=35
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,599 ] reached end of chunk seq=36
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,601 ] reached end of chunk seq=37
1675014014.55328
271675014014.553
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,603 ] reached end of chunk seq=38
52881675014014.5
5369881675014014
.553859167501401
4.55401091675014
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,605 ] reached end of chunk seq=39
014.554161167501
4014.55431316750
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,606 ] reached end of chunk seq=40
14014.5544496167
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,607 ] reached end of chunk seq=41
5014014.55457691
675014014.554707
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,609 ] reached end of chunk seq=42
31675014014.5548
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,610 ] reached end of chunk seq=43
4081675014014.55
497621675014014.
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,611 ] reached end of chunk seq=44
5551155167501401
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,612 ] reached end of chunk seq=45
4.55524731675014
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,614 ] reached end of chunk seq=46
014.555366516750
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,615 ] reached end of chunk seq=47
14014.5555098167
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,616 ] reached end of chunk seq=48
5014014.55564861
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,617 ] reached end of chunk seq=49
675014014.555772
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,618 ] reached end of chunk seq=50
1675014014.55588
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,619 ] reached end of chunk seq=51
651675014014.555
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,620 ] reached end of chunk seq=52
99951675014014.5
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,621 ] reached end of chunk seq=53
5611251675014014
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,622 ] reached end of chunk seq=54
.556225167501401
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,624 ] reached end of chunk seq=55
4.55634121675014
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,625 ] reached end of chunk seq=56
014.556414416750
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,626 ] reached end of chunk seq=57
14014.5564578167
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,627 ] reached end of chunk seq=58
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,628 ] reached end of chunk seq=59
5014014.55650041
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,629 ] reached end of chunk seq=60
675014014.556534
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,630 ] reached end of chunk seq=61
51675014014.5565
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,631 ] reached end of chunk seq=62
7081675014014.55
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,633 ] reached end of chunk seq=63
66151675014014.5
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,634 ] reached end of chunk seq=64
5665351675014014
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,635 ] reached end of chunk seq=65
.556690216750140
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,636 ] reached end of chunk seq=66
14.5567276167501
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,638 ] reached end of chunk seq=67
4014.55676441675
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,639 ] reached end of chunk seq=68
014014.556801616
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,640 ] reached end of chunk seq=69
75014014.5568416
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,641 ] reached end of chunk seq=70
1675014014.55689
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,643 ] reached end of chunk seq=71
79
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,644 ] reached end of chunk seq=72
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,645 ] reached end of chunk seq=73
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,646 ] reached end of chunk seq=74
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,647 ] reached end of chunk seq=75
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,648 ] reached end of chunk seq=76
[DEBUG ] [SRUDP     ] [2023-01-29 17:40:14,649 ] reached end of chunk seq=77
1675014014.55694
(...)

OUTPUT SIDE B:

[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,246 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,248 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,249 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,250 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,251 ] send operation success 17b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,257 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,257 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,259 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,260 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,261 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,263 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,264 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,266 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,268 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,270 ] send operation success 18b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,270 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,272 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,273 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,275 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,277 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,279 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,281 ] send operation success 18b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,282 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,283 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,284 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,285 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,287 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,289 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,291 ] send operation success 18b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,292 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,294 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,295 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,296 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,297 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,299 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,301 ] send operation success 16b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,303 ] send operation success 17b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,303 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,305 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,307 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,310 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,312 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,314 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,316 ] send operation success 18b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,316 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,317 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,319 ] send operation success 17b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,320 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,321 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,322 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,324 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,326 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,329 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,331 ] send operation success 18b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,331 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,333 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,334 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,335 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,337 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,339 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,342 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,346 ] send operation success 18b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,346 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,348 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,349 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,350 ] send operation success 18b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,351 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,353 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,354 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,356 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,359 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,362 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,365 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,367 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,370 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,374 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,379 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,384 ] send operation success 17b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,386 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,387 ] send operation success 18b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,389 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,391 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,394 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,397 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,399 ] send operation success 18b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,400 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,401 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,403 ] send operation success 18b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,403 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,405 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,407 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,410 ] send operation success 18b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,414 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,414 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,415 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,417 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,418 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,419 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,420 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,422 ] send operation success 16b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,426 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,428 ] send operation success 18b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,428 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,430 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,432 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,433 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,435 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,438 ] send operation success 18b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,439 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,441 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,443 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,446 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,449 ] send operation success 17b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,450 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,452 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,453 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,455 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,458 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,461 ] send operation success 17b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,462 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,463 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,465 ] send operation success 18b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,470 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,473 ] send operation success 17b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,475 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,476 ] send operation success 18b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,478 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,482 ] send operation success 18b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:32,483 ] allow sending operation again seq=523
[DEBUG ] [MainThread] [2023-01-29 14:40:32,484 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,486 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,487 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,488 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,491 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,493 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,495 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,496 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,497 ] send operation success 17b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,498 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,500 ] send operation success 18b
[DEBUG ] [MainThread] [2023-01-29 14:40:32,501 ] buffer is full and wait for signaled
[DEBUG ] [MainThread] [2023-01-29 14:40:32,501 ] send operation success 17b
[DEBUG ] [SRUDP     ] [2023-01-29 14:40:37,432 ] srudp socket is closing now
[DEBUG ] [MainThread] [2023-01-29 14:40:53,502 ] waiting for sending buffer have space..
[DEBUG ] [MainThread] [2023-01-29 14:41:14,505 ] waiting for sending buffer have space..
[DEBUG ] [MainThread] [2023-01-29 14:41:35,508 ] waiting for sending buffer have space..
[DEBUG ] [MainThread] [2023-01-29 14:41:56,511 ] waiting for sending buffer have space..
(...)

As can be seen, the data stream becomes unstable in terms of both the data and the behavior of the program.
I think the best thing to do would be to lock the socket until the completion of the operation is verified.

@namuyan
Copy link
Owner

namuyan commented Feb 2, 2023

I'm reading code after 2 years.
I find self.sendto() is guarded by self.sender_buffer_lock.

I tested your simple debug code, I can't reproduce your errors, but add some fix.
Please check..

@uint69-t
Copy link
Author

uint69-t commented Feb 2, 2023

I really dont know, im using Python 3.9.16, maybe some threading behavior changed?

Im out of ideas, if i "manually" sleep for a couple of ms it works perfect, but if i just "while True" seems like the software isnt capable of handling the data-flow and when the send_buffer gets full starts sending random bytes from the top of the buffer (?)

if you can provide me with some idea to just add a variable "bool sending" to lock the buffer input while sending i can implement it.

Thanks for your reply.
~ uint69_t

@namuyan
Copy link
Owner

namuyan commented Feb 4, 2023

I find bug in my code.

https://github.com/namuyan/srudp/blob/master/srudp/__init__.py#L587
This bug becomes apparent when re-transmit PSH packet.

I need fix logics, it will take some time to fix.

@namuyan
Copy link
Owner

namuyan commented Feb 6, 2023

86a77d1
The bug may be fixed by this commit, please check.

memo: sender_buffer is locked but sender_socket is not locked, it may cause exception.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@namuyan @uint69-t