timeout bug about P2 timer

xinkunlong commented 3 years ago

Please analyze the log and focus on the timestamp in the bold part

From the application layer sending the message request to PCAN sending the message, it has already consumed about 49ms, so there will be a timeout, How should we deal with this bug? Tank you!

2021-06-05 23:25:37,170 [INFO] Connection: Connection opened 2021-06-05 23:25:37,173 [INFO] UdsClient: DiagnosticSessionControl<0x10> - Switching session to defaultSession (0x01) 2021-06-05 23:25:37,173 [DEBUG] UdsClient: Sending request to server 2021-06-05 23:25:37,174 [DEBUG] Connection: Sending 2 bytes : [b'1001'] 2021-06-05 23:25:37,174 [DEBUG] UdsClient: Waiting for server response 2021-06-05 23:25:37,223 [DEBUG] can.pcan: Sending 8 bytes : [b'0210015555555555'] 2021-06-05 23:25:37,273 [DEBUG] can.pcan: Received 8 bytes : [b'065001003200c8aa'] 2021-06-05 23:25:37,273 [DEBUG] Connection: Received 6 bytes : [b'5001003200c8'] 2021-06-05 23:25:37,274 [DEBUG] UdsClient: Received response from server 2021-06-05 23:25:37,274 [INFO] UdsClient: Received positive response for service DiagnosticSessionControl (0x10) from server. 2021-06-05 23:25:37,275 [INFO] UdsClient: DiagnosticSessionControl<0x10> - Received new timing parameters. P2=0.050s and P2*=2.000s. Using these value from now on. 2021-06-05 23:25:37,275 [INFO] UdsClient: DiagnosticSessionControl<0x10> - Switching session to extendedDiagnosticSession (0x03) 2021-06-05 23:25:37,276 [DEBUG] UdsClient: Sending request to server 2021-06-05 23:25:37,276 [DEBUG] Connection: Sending 2 bytes : [b'1003'] 2021-06-05 23:25:37,276 [DEBUG] UdsClient: Waiting for server response 2021-06-05 23:25:37,324 [DEBUG] can.pcan: Sending 8 bytes : [b'0210035555555555'] 2021-06-05 23:25:37,329 [DEBUG] Connection: No data received: [TimeoutException] - Did not receive frame IsoTP Transport layer in time (timeout=0.05 sec) 2021-06-05 23:25:37,329 [ERROR] UdsClient: [TimeoutException] : Did not receive response in time. P2 timeout time has expired (timeout=0.050 sec) 2021-06-05 23:25:37,375 [INFO] Connection: Connection closed

ECU: P2 = 50MS, P2* =2000MS

device ：PCAN-USB IPEH-002021

Name: udsoncan Version: 1.13.1

Python 3.8.8 (tags/v3.8.8:024d805, Feb 19 2021, 13:18:16) [MSC v.1928 64 bit (AMD64)] on win32


        with client.Client(conn=self.canCom,config=uds_config) as cli:

            cli.change_session(services.DiagnosticSessionControl.Session.defaultSession)

            cli.change_session(services.DiagnosticSessionControl.Session.extendedDiagnosticSession)

pylessard commented 3 years ago

Hi, 50msec is a very short timeout. Windows has a thread resolution of 16ms, it will be hard to respect this timing

You can ask the client to ignore the server timeout with the following config: use_server_timing = False

https://udsoncan.readthedocs.io/en/latest/udsoncan/client.html#use_server_timing

xinkunlong commented 3 years ago

OK, thanks!

MasterCodeIT commented 3 years ago

[INFO] Connection: Connection opened [INFO] UdsClient: DiagnosticSessionControl<0x10> - Switching session to extendedDiagnosticSession (0x03) [DEBUG] Connection: Sending 2 bytes : [b'1003'] [DEBUG] Connection: No data received: [TimeoutException] - Did not received ISOTP frame in time (timeout=2 sec) [ERROR] UdsClient: [TimeoutException] : Did not receive response in time. P2 timeout time has expired (timeout=2.000 sec) [INFO] Connection: Connection closed

I changed the use_server_timing = False but now triggering this:

[INFO] Connection: Connection opened [INFO] UdsClient: DiagnosticSessionControl<0x10> - Switching session to extendedDiagnosticSession (0x03) [DEBUG] Connection: Sending 2 bytes : [b'1003'] DEBUG] Connection: No data received: [TimeoutException] - Did not received ISOTP frame in time (timeout=1.998906135559082 sec) [ERROR] UdsClient: [TimeoutException] : Did not receive response in time. Global request timeout time has expired (timeout=1.999 sec) [INFO] Connection: Connection closed

pylessard commented 3 years ago

Well, you haven't received anything withon 3 secs. So either your server did not respond, you haven't configured your address correctly or another task is reading the python-can bus emptying the rx buffer.

MasterCodeIT commented 3 years ago

I found something interesting on this ECU/vehicle, so when sending the request for vin, seems when I send it manually, I need the add an additional data "00000000".

When I manually send 8 bytes:

cansend can0 7e0#0322F19000000000
I received a positive response from rxid 7e8

I decided to run a test use the ECU reset. I manually sent:

cansend can0 7e0#0211010000000000
candump can0 showed a postive response received by rxid 7e8

When I apply the udsoncan ECUReset, it only sends bytes and I get the following: [INFO] Connection: Connection opened [INFO] UdsClient: ECUReset<0x11> - Requesting reset of type 0x01 (hardReset) [DEBUG] Connection: Sending 2 bytes : [b'1101'] [DEBUG] Connection: No data received: [TimeoutException] - Did not received ISOTP frame in time (timeout=1.9986445903778076 sec) [ERROR] UdsClient: [TimeoutException] : Did not receive response in time. Global request timeout time has expired (timeout=1.999 sec) [INFO] Connection: Connection closed

candump can0 showing no response from rxid 7e8 and the sent only bytes 021101

So the ECU only gets a response when all 8 bytes are sent so my questions is, how can I have udsoncan apply the additional bytes missing?

pylessard commented 3 years ago

Hi, So your server expects zero-padding. this is done at the transport layer level, not at the UDS level. If you use my IsoTP library, you can set a padding of 8 bytes and it will do as you need.

You need to set : tx_data_min_length = 8 tx_padding = 0

Also, I noticed that you seem to be working on a platform very similar to the one presented in #80. Is it related?

MasterCodeIT commented 3 years ago

Hi, So your server expects zero-padding. this is done at the transport layer level, not at the UDS level. If you use my IsoTP library, you can set a padding of 8 bytes and it will do as you need.

You need to set : tx_data_min_length = 8 tx_padding = 0

Also, I noticed that you seem to be working on a platform very similar to the one presented in #80. Is it related?

Yes similar! I am attempting to use your isotp that you recommended but am having a new error.

Code:

bus = can.interface.Bus(channel="can0", bustype="socketcan", fd=True)
tp_addr = isotp.Address(isotp.AddressingMode.Normal_11bits, txid=0x7e0, rxid=0x7e8)
stack = isotp.CanStack(bus=bus, address=tp_addr, params=isotp_params)
conn = PythonIsoTpConnection(stack)
with Client(conn,  request_timeout=2, config=config) as client:
        client.ecu_reset(ECUReset.ResetType.hardReset),
        print("reset done")

So I attempted to run some of your example for isotp but results to the following error:

Failed to transmit: [Errno 22] Invalid argument
[TimeoutException] : Did not receive response in time. Global request timeout time has expired (timeout=2.000 sec)
Traceback (most recent call last):
  File "/home/pi/.local/lib/python3.7/site-packages/udsoncan/client.py", line 1647, in send_request
    payload = self.conn.wait_frame(timeout=timeout_value, exception=True)

pylessard commented 3 years ago

Have you set the padding in the isotp layer parameters?

MasterCodeIT commented 3 years ago

Have you set the padding in the isotp layer parameters?

For those following, always trace back your steps! A minor typo of:

"tx_data_min_length" (correct)
"tx_data_min_length " (incorrect -> see the space after length ;p)

Brings us back to the original issue of the vin. (using your example)


   response = client.read_data_by_identifier(0xF190)
   print(response.service_data.values[0xF190]) 
   vin = client.read_data_by_identifier_first(0xF190)
   print(vin)  # 'ABCDE0123456789' (15 chars)

[ERROR] UdsClient: [InvalidResponseException] : ReadDataByIdentifier service execution returned an invalid response. Value for data identifier 0x3932 was incomplete according to definition in configuration
2021-06-07 17:55:26 [INFO] Connection: Connection closed
Traceback (most recent call last):
  File "/home/pi/udsoncan/can-isotp-vin.py", line 62, in <module>
    response = client.read_data_by_identifier(0xF190)
  File "/home/pi/.local/lib/python3.7/site-packages/udsoncan/client.py", line 131, in decorated
    return func(self, *args, **kwargs)
  File "/home/pi/.local/lib/python3.7/site-packages/udsoncan/client.py", line 397, in read_data_by_identifier
    services.ReadDataByIdentifier.interpret_response(response, **params)
  File "/home/pi/.local/lib/python3.7/site-packages/udsoncan/services/ReadDataByIdentifier.py", line 131, in interpret_response
    raise InvalidResponseException(response, "Value for data identifier 0x%04x was incomplete according to definition in configuration" % did)
udsoncan.exceptions.InvalidResponseException: ReadDataByIdentifier service execution returned an invalid response. Value for data identifier 0x3932 was incomplete according to definition in configuration

pylessard commented 3 years ago

Now it's working, but you are using a codec definition that doesn't match what your server provides. Use your code instead of mine and all should be good

MasterCodeIT commented 3 years ago

Good stuff! Works well and love the response time!

tiger86023086 commented 3 years ago

When I use the code:

 isotp_params = {
   'stmin':32,                          # Will request the sender to wait 32ms between consecutive frame. 0-127ms or 100-900ns with values from 0xF1-0xF9
   'blocksize':8,                       # Request the sender to send 8 consecutives frames before sending a new flow control message
   'wftmax':0,                          # Number of wait frame allowed before triggering an error
   'tx_data_length':8,                 # Link layer (CAN layer) works with 8 byte payload (CAN 2.0)
   'tx_data_min_length':8,         # Minimum length of CAN messages. When different from None, messages are padded to meet this length. Works with CAN 2.0 and CAN FD.
   'tx_padding':0x55,                      # Will pad all transmitted CAN messages with byte 0x00.
   'rx_flowcontrol_timeout':1000,       # Triggers a timeout if a flow control is awaited for more than 1000 milliseconds
   'rx_consecutive_frame_timeout':1000, # Triggers a timeout if a consecutive frame is awaited for more than 1000 milliseconds
   'squash_stmin_requirement':False,    # When sending, respect the stmin requirement of the receiver. If set to True, go as fast as possible.
   'max_frame_size':4095               # Limit the size of receive frame.
}

mybus = can.Bus(bustype='canalystii', channel=0, bitrate=500000)

config = dict(udsoncan.configs.default_client_config)

config['use_server_timing'] = False
config['p2_timeout'] = 5
config['p2_star_timeout'] = 5

tp_addr = isotp.Address(isotp.AddressingMode.Normal_11bits, txid=0x731, rxid=0x739) # Network layer addressing scheme
stack = isotp.CanStack(bus=mybus, address=tp_addr, params=isotp_params)               # Network/Transport layer (IsoTP protocol)
conn = PythonIsoTpConnection(stack)                                                 # interface between Application and Transport layer
with Client(conn,config=config) as client:                                     # Application layer (UDS protocol)
    client.change_session(1)

[TimeoutException] : Did not receive response in time. Global request timeout time has expired (timeout=5.000 sec)
Traceback (most recent call last):
  File "D:\Python37\lib\site-packages\udsoncan\client.py", line 1647, in send_request
    payload = self.conn.wait_frame(timeout=timeout_value, exception=True)
  File "D:\Python37\lib\site-packages\udsoncan\connections.py", line 68, in wait_frame
    frame = self.specific_wait_frame(timeout=timeout)
  File "D:\Python37\lib\site-packages\udsoncan\connections.py", line 490, in specific_wait_frame
    raise TimeoutException("Did not receive frame IsoTP Transport layer in time (timeout=%s sec)" % timeout)
udsoncan.exceptions.TimeoutException: Did not receive frame IsoTP Transport layer in time (timeout=5.0 sec)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "E:\Project\ProCCMTest\ProCCMTest\code\debug\canalystiidebugUDS1.py", line 41, in <module>
    client.change_session(1)
  File "D:\Python37\lib\site-packages\udsoncan\client.py", line 131, in decorated
    return func(self, *args, **kwargs)
  File "D:\Python37\lib\site-packages\udsoncan\client.py", line 189, in change_session
    response = self.send_request(req)
  File "D:\Python37\lib\site-packages\udsoncan\client.py", line 1655, in send_request
    raise TimeoutException('Did not receive response in time. %s time has expired (timeout=%.3f sec)' % (timeout_name_to_report, timeout_value))
udsoncan.exceptions.TimeoutException: Did not receive response in time. Global request timeout time has expired (timeout=5.000 sec)

2021-06-22 16:02:10 [INFO] Connection: Connection opened 2021-06-22 16:02:10 [INFO] UdsClient: DiagnosticSessionControl<0x10> - Switching session to defaultSession (0x01) 2021-06-22 16:02:10 [DEBUG] Connection: Sending 2 bytes : [b'1001'] 2021-06-22 16:02:15 [DEBUG] Connection: No data received: [TimeoutException] - Did not receive frame IsoTP Transport layer in time (timeout=5 sec) 2021-06-22 16:02:15 [ERROR] UdsClient: [TimeoutException] : Did not receive response in time. P2 timeout time has expired (timeout=5.000 sec) 2021-06-22 16:02:15 [INFO] Connection: Connection closed

But actualy i rececive the positive response. i don't know why?

pylessard / python-udsoncan

timeout bug about P2 timer #87