Isotp Transport layer can't recieve can in time

[XXIN0]

Hi, the server is response the request timely,but the IsoTP Transport layer didn’t recieve the can msg in time. the code is same as issue pylessard/python-can-isotp#50

INFO Connection:connections.py:449 Connection opened DEBUG Connection:connections.py:51 Sending 2 bytes : [b'1001'] DEBUG isotp:protocol.py:478 Sending : <701> (8) b'0210010000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892866.389645 <701> (8) b'0210010000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892866.391792 <781> (8) b'065001003201f400' DEBUG Connection:connections.py:78 Received 6 bytes : [b'5001003201f4'] DEBUG Connection:connections.py:51 Sending 2 bytes : [b'1003'] DEBUG isotp:protocol.py:478 Sending : <701> (8) b'0210030000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892866.523789 <701> (8) b'0210030000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892866.526788 <781> (8) b'065003003201f400' DEBUG Connection:connections.py:78 Received 6 bytes : [b'5003003201f4'] DEBUG Connection:connections.py:51 Sending 2 bytes : [b'2701'] DEBUG isotp:protocol.py:478 Sending : <701> (8) b'0227010000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892866.649799 <701> (8) b'0227010000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892866.651773 <781> (8) b'066701cca8f3b600' DEBUG Connection:connections.py:78 Received 6 bytes : [b'6701cca8f3b6'] DEBUG Connection:connections.py:51 Sending 6 bytes : [b'270200000000'] DEBUG isotp:protocol.py:478 Sending : <701> (8) b'0627020000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892866.796657 <701> (8) b'0627020000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892866.801785 <781> (8) b'037f273500000000' DEBUG Connection:connections.py:78 Received 3 bytes : [b'7f2735'] DEBUG Connection:connections.py:51 Sending 2 bytes : [b'1003'] DEBUG isotp:protocol.py:478 Sending : <701> (8) b'0210030000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892866.988792 <701> (8) b'0210030000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892866.991774 <781> (8) b'065003003201f400' DEBUG Connection:connections.py:78 Received 6 bytes : [b'5003003201f4'] DEBUG Connection:connections.py:51 Sending 2 bytes : [b'2701'] DEBUG isotp:protocol.py:478 Sending : <701> (8) b'0227010000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892867.383900 <701> (8) b'0227010000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892867.386743 <781> (8) b'06670119694e7900' DEBUG Connection:connections.py:78 Received 6 bytes : [b'670119694e79'] DEBUG Connection:connections.py:51 Sending 6 bytes : [b'270200000000'] DEBUG isotp:protocol.py:478 Sending : <701> (8) b'0627020000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892868.215265 <701> (8) b'0627020000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892868.216732 <781> (8) b'037f273500000000' DEBUG Connection:connections.py:78 Received 3 bytes : [b'7f2735'] DEBUG Connection:connections.py:51 Sending 2 bytes : [b'1003'] DEBUG isotp:protocol.py:478 Sending : <701> (8) b'0210030000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892869.103942 <701> (8) b'0210030000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892869.106686 <781> (8) b'065003003201f400' DEBUG Connection:connections.py:78 Received 6 bytes : [b'5003003201f4'] DEBUG Connection:connections.py:51 Sending 2 bytes : [b'2701'] DEBUG isotp:protocol.py:478 Sending : <701> (8) b'0227010000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892869.493930 <701> (8) b'0227010000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892869.496674 <781> (8) b'066701b67e020900' DEBUG Connection:connections.py:78 Received 6 bytes : [b'6701b67e0209'] DEBUG Connection:connections.py:51 Sending 6 bytes : [b'270200000000'] DEBUG isotp:protocol.py:478 Sending : <701> (8) b'0627020000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892870.024165 <701> (8) b'0627020000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892870.026656 <781> (8) b'037f273600000000' DEBUG Connection:connections.py:78 Received 3 bytes : [b'7f2736'] DEBUG Connection:connections.py:51 Sending 2 bytes : [b'1003'] DEBUG isotp:protocol.py:478 Sending : <701> (8) b'0210030000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892870.319511 <701> (8) b'0210030000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892870.321641 <781> (8) b'065003003201f400' DEBUG Connection:connections.py:78 Received 6 bytes : [b'5003003201f4'] DEBUG Connection:connections.py:51 Sending 2 bytes : [b'2701'] DEBUG isotp:protocol.py:478 Sending : <701> (8) b'0227010000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892870.787709 <701> (8) b'0227010000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892870.791616 <781> (8) b'037f273700000000' DEBUG Connection:connections.py:78 Received 3 bytes : [b'7f2737'] DEBUG Connection:connections.py:51 Sending 2 bytes : [b'1003'] DEBUG isotp:protocol.py:478 Sending : <701> (8) b'0210030000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892871.372225 <701> (8) b'0210030000000000' DEBUG isotp:protocol.py:471 Receiving : 1627892871.376599 <781> (8) b'065003003201f400' DEBUG Connection:connections.py:78 Received 6 bytes : [b'5003003201f4'] DEBUG Connection:connections.py:51 Sending 6 bytes : [b'270200000000'] DEBUG isotp:protocol.py:478 Sending : <701> (8) b'0627020000000000' DEBUG Connection:connections.py:70 No data received: [TimeoutException] - Did not receive frame IsoTP Transport layer in time (timeout=2 sec)

[pylessard]

My feeling is that something else is "consuming" the message from the Bus object. Do you call bus.recv somewhere in your code?

[XXIN0]

I don‘t call bus.recv in other place

[pylessard]

This is strange, it should've worked. Do you call process in a loop? does it have a dedicated thread or is it embedded into another task that can block?

[XXIN0]

I think I didn't call process in a loop I've e-mailed the code to you,thank you.

[pylessard]

Hi, I've looked at the code you sent me through email. I see that you use pytest to launch your UDS operation. I am not very familiar with pytest, but I wonder if the test really execute the way they should. It looks like each test setup an IsoTP channel, does the test then close it.

Are you really sure that when a test start, that the previous has completed its shutdown sequence? Many behavior that you described could be explained if another parallel channel would interfere.

Just for testing purpose, can you try to add a blocking delay after you call close_can?

[XXIN0]

ok，I'll test it tomorrow then tell you the result,thank you !

[XXIN0]

Hi,

1. I try to add sleep(1) after call close_can,the flow control frame will also timeout.

2. I ‘m not sure that when a new testcase start weather the previous has completed its shutdown sequence or not. The test process is shown in the following figure.

ps: It also can setup and teardowm within the scope of class

[jagauthier]

I realize this is an older thread, but I am having this issue as well. In my case I am sending large chunk of data, and I see it's on the bus but isotp says it's not being received in time.

I am sending string "01234567890ABCDEFGHIJKLMNOPQRSTUVWXYZ01234567890ABCDEFGHIJKLMNOPQRSTUVWXYZ01234567890ABCDEFGHIJKLMNOPQRSTUVWXYZ01234567890ABCDEFGHIJKLMNOPQRSTUVWXYZ"

Can dump shows me this:

 (1647780103.650365)  can0  100   [8]  10 B9 30 31 32 33 34 35
 (1647780103.650587)  can0  100   [8]  21 36 37 38 39 30 41 42
 (1647780103.650837)  can0  100   [8]  22 43 44 45 46 47 48 49
 (1647780103.651038)  can0  100   [8]  23 4A 4B 4C 4D 4E 4F 50
 (1647780103.651276)  can0  100   [8]  24 51 52 53 54 55 56 57
 (1647780103.651494)  can0  100   [8]  25 58 59 5A 30 31 32 33
 (1647780103.651727)  can0  100   [8]  26 34 35 36 37 38 39 30
 (1647780103.651957)  can0  100   [8]  27 41 42 43 44 45 46 47
 (1647780103.652185)  can0  100   [8]  28 48 49 4A 4B 4C 4D 4E
 (1647780103.652418)  can0  100   [8]  29 4F 50 51 52 53 54 55
 (1647780103.652650)  can0  100   [8]  2A 56 57 58 59 5A 30 31
 (1647780103.652894)  can0  100   [8]  2B 32 33 34 35 36 37 38
 (1647780103.653114)  can0  100   [8]  2C 39 30 41 42 43 44 45
 (1647780103.653343)  can0  100   [8]  2D 46 47 48 49 4A 4B 4C
 (1647780103.653595)  can0  100   [8]  2E 4D 4E 4F 50 51 52 53
 (1647780103.653813)  can0  100   [8]  2F 54 55 56 57 58 59 5A
 (1647780103.654040)  can0  100   [8]  20 30 31 32 33 34 35 36
 (1647780103.654269)  can0  100   [8]  21 37 38 39 30 41 42 43
 (1647780103.654516)  can0  100   [8]  22 44 45 46 47 48 49 4A
 (1647780103.654733)  can0  100   [8]  23 4B 4C 4D 4E 4F 50 51
 (1647780103.654963)  can0  100   [8]  24 52 53 54 55 56 57 58
 (1647780103.655192)  can0  100   [8]  25 59 5A 30 31 32 33 34
 (1647780103.655430)  can0  100   [8]  26 35 36 37 38 39 30 41
 (1647780103.655655)  can0  100   [8]  27 42 43 44 45 46 47 48
 (1647780103.655898)  can0  100   [8]  28 49 4A 4B 4C 4D 4E 4F
 (1647780103.656122)  can0  100   [8]  29 50 51 52 53 54 55 56
 (1647780103.656266)  can0  100   [2]  2A 57
 (1647780103.680604)  can0  123   [3]  30 08 00
 (1647780103.703996)  can0  123   [3]  30 08 00

Python isotp code tell me this:

WARNING:root:IsoTp error happened : ConsecutiveFrameTimeoutError - Reception of CONSECUTIVE_FRAME timed out.
WARNING:isotp:Reception of CONSECUTIVE_FRAME timed out.

I'm using example code to receive:

if __name__ == '__main__':
    app = ThreadedApp()
    app.start()

    print('Waiting for payload - maximum 10 sec')
    t1 = time.time()
    while 1:
        if app.stack.available():
            payload = app.stack.recv()
            print("Received payload : %s" % (payload))
        time.sleep(0.2)

    print("Exiting")
    app.shutdown()

[pylessard]

Hi @jagauthier. I am not sure if it is related, but the sending device doesn't wait for flow control before proceding with consecutive frames. We see 2 flow controls eith id 123 at the end.

[jagauthier]

True. I have not implemented flow control in my half yet. I will do so and verify.

[pylessard]

@jagauthier : I think the flow control timing is not the issue here. You seem to be missing data for real. The data ends at 57 which is W not Z. There is 25 Full CF and 1 CF of 1 bytes. That makes 6+25*7+1 = 182 which is B6, not B9

[jagauthier]

@pylessard Yup, you're right. My calculation of length (with headers) was off. I fixed the calculation and everything is fine. So, nothing related to this issue at all.

[pylessard]

Should we close that?

[XXIN0]

Can‘t be stable recurrence,close issue.