[sshane]

To fix an issue with #24706, we don't consider response pending responses, so we would break before some queries finish if our queries complete fast enough

• Tracks timeouts per address
• Per discussion with Greg, we've seen some VW ECUs take up to 6 seconds between response pending responses, so choose timeout of 10 seconds for addresses with a response pending.
• Continually receiving response pending from an ECU is rare, so raise max timeout to 1 minute
• Every time an ecu responds with response pending, wait additional 10 seconds for response, then set timeout to default 0.1 seconds on valid response, and the next loop we'll break if we've gotten everything

Implementation done in panda for UdsClient, brought over for fw fingerprinting commaai/panda#723

[sshane]

@gregjhogan Do you know why we do https://github.com/commaai/openpilot/blob/master/selfdrive/car/fw_versions.py#L335? Can we remove it?

[pd0wm]

Think the first iteration you have a larger batch? Remember adding that to make toyota more reliable.

[sshane]

I see, looks like these are the number of addresses in the batches: [5, 7, 7, 13, 6, 6, 6, 5, 5, 6, 6, 6, 6, 2, 1, 1, 1, 1, 1, 1]

[pd0wm]

Ah ok, maybe other changes were made in the meantime that make this no longer relevant. If it works fine on Toyota you can remove it.

[sshane]

If we keep as a safety net I'm fine with that, once everything completes we break anyway

[jyoung8607]

• Per discussion with Greg, we've seen some VW ECUs take up to 6 seconds between response pending responses, so choose timeout of 10 seconds for addresses with a response pending.
• Continually receiving response pending from an ECU is rare, so raise max timeout to 1 minute
• Every time an ecu responds with response pending, wait additional 10 seconds for response, then set timeout to default 0.1 seconds on valid response, and the next loop we'll break if we've gotten everything

I can't remember how long our worst-case response to a query was (there were some long ones but not fingerprint-relevant). However, IIRC the timer was set to 6 seconds because the relevant ISO UDS standard calls for a module to repeat its 0x7fXX78 please-wait response every 5 seconds until it's ready to answer. So 10 seconds is exceedingly generous.

[sshane]

@gregjhogan what do you think? Is 6 seconds good instead of 10?

[sshane]

Just timed the FW queries on the Optima, it takes 3.9 seconds on average! We don't get any response pending responses from any ECU here, so of course it no change in the time on this car. @jyoung8607 can you time this branch before and after for the FW queries?

[gregjhogan]

Notes from past PRs related to this PR ...
UDS timeouts: commaai/panda#699 (comment)
indication that an ECU needed more than a 5 second timeout after response pending: commaai/panda#699 (comment)

So it seems like we need something higher than a 5 second response pending timeout. The problem with going to short is the responses might get mixed up. I am not sure how to determine if 6 seconds is sufficient because so few ECUs use response pending for firmware queries. The only place I have personally seen it is when you ask an ECU to erase flash or compute a checksum on the firmware.

Also, if the only ECUs using response pending are things openpilot does not directly interface with for driving (e.g. airbags) maybe we should eliminate these from firmware querying.

[jyoung8607]

Also, if the only ECUs using response pending are things openpilot does not directly interface with for driving (e.g. airbags) maybe we should eliminate these from firmware querying.

I want to keep it for the time being. Without it, I lose some insurance that I can discriminate between similar models.

My first and best discriminator between models is the last part of three-part EPS query, the steering characteristic map identifier returned from 0xF182 APPLICATION_DATA_IDENTIFICATION. But, the blessing and curse of VW MQB is they're all so similar, and almost everything else ends up being shareable between models with differing mass and wheelbase.

I added the airbag config data because I wanted extra insurance, something else that varied with different model/chassis dynamics, different mass and wheelbase combinations. I was worried about hanging my hat exclusively on the EPS map, and getting in trouble later after we'd upstreamed a bunch of models already, when it would be much harder to fix. In fact, this has now happened (#23735).

What I really wanted was the ABS/ESP firmware, but I couldn't make it work back in the day because (drumroll!) this same problem where it returned a delayed response. Now that the parallel query is fixed, and especially now with whitelisting to tailor specialized queries to individual modules, I'd transition away from SRS if it were easy. But making that switch today would be Kind of a Big Deal, and it wouldn't let us sidestep handling of delayed responses. I do think it's worth doing someday.

[jyoung8607]

@jyoung8607 can you time this branch before and after for the FW queries?

Did five test runs of each variant with full output on my side to make sure all FW returned, followed by another five stripped down to just the timing output.

TL;DR: new timeout code doesn't hurt, whitelisting helps, and my SRS doesn't take very long to reply.

procedure:

comma@tici:/data$ cat time-fp.sh 
#!/bin/bash

for i in {1..5}
do
  /data/openpilot/selfdrive/car/fw_versions.py 2>/dev/null | grep "Possible matches\|Getting fw took"
done

master:

comma@tici:/data$ ./time-fp.sh 
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 3.889 s
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 3.901 s
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 3.921 s
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 3.919 s
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 3.935 s

isotp-parallel-response-pending:

comma@tici:/data/openpilot$ ../time-fp.sh 
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 3.898 s
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 3.907 s
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 3.920 s
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 3.909 s
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 3.923 s

isotp-parallel-response-pending + whitelists from #24706:

comma@tici:/data/openpilot$ ../time-fp.sh 
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 3.486 s
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 3.499 s
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 3.483 s
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 3.487 s
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 3.501 s

isotp-parallel-response-pending + whitelists from #24706 + stripped to VW queries only:

comma@tici:/data/openpilot$ ../time-fp.sh 
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 0.240 s
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 0.250 s
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 0.261 s
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 0.257 s
Possible matches: {'VOLKSWAGEN GOLF 7TH GEN'}
Getting fw took 0.273 s

[jyoung8607]

indication that an ECU needed more than a 5 second timeout after response pending: commaai/panda#699 (comment)

That only happens with one non-standard undocumented UDS data identifier from my Telematics module, that returns something absurdly long after a delay. I think it could be GPS or cell network info. Not really something openpilot needs to handle, and retesting right now it's only taking about 3-4 seconds anyway.

There's not much harm in a longer timeout, chances of the conversation breaking down after a successful interim response are fairly low, was just highlighting the thought processes behind 5 vs 6 vs 10 seconds.

ISO-TP: RESPONSE - 0x7d1 0x22f15b0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000040001beb0001000040001beb032c70000000000000000001000000000000000000000000000000000000000040001be90000000040001beb00007000000000000000000100000000000f00004000426c400042304000431400120000400043c0400043204000445000930000400048c040004460400054ac00060000400055a8400054c8400055a800080000400055ec400055c8400056c4000a0000400057b4400056e84000594c001a000040005ea04000599040007e44000000000000000000000000000000000000000000001a000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000001a54588b00130450361614010a0000000000000000000001c700a98a2d01c700b67ac100e286000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000008003e300000000000000000000000000000000000000000000000000000000000003e30000000000000000000000000000000000000000000000000000000000000002080404000021044401190400005caa0000086868686863656862626808

[sshane]

I'm fine with 10 seconds if it will ensure we wait for all responses, this look good @gregjhogan?

[gregjhogan]

Seems like you want to set the timeout to the current time any time you set an addr as done so you don't wait an extra timeout period below where it waits for the max timeout to be expired.

[sshane]

A lot of the requests are of len 1, so it's possible for a brand we quit early if we never increment the counter if we only get "done" responses. What's on the branch is similar to the previous behavior of increasing the timeout for any response

[gregjhogan]

I am saying you break out of the loop when cur_time - max(response_timeouts.values()) > 0 meaning after you get the last good response message you increment the timer for that rx addr and then wait for it to expire (but don't need to) but maybe this isn't worth worrying about.

[sshane]

When everything is received we break anyway.

if all(request_done.values()):
  break

[gregjhogan]

yeah, so it only waits longer than it needs to when some requests do not complete (and those requests time out before the last successful request succeeds) not sure if it is worth shaving off that 0.1 s in that scenario

[sshane]

Yeah. If we don't increment on a done response, what if we get a bunch of single frame done responses? It would eventually timeout

[sshane]

This is the current behavior too, so I think this is okay to merge. We can adjust the timeout in another PR