Carbibbles wrote:
Dale, finally got a chance to get a trace log. The issue happened every time if the "log with defrost" option was turned on. It also didn't matter if I turned the key to acc. or completely off. Hopefully the log can show what is happening. I included the csv log that was created.
Jason
This log is kinda messed up.
First suggestion for you, since you don't appear to have LogWorks3 installed on that computer, pull the LM-2 (mts) plugin out of the \plugins directory to stop it from trying to load. You can always put it back if you want to use it later. The Logger will start up faster too!
Next I see this odd thing:
Code:
166676 INFO [Thread-26] - Trying J2534 connection...
166676 INFO [Thread-26] - J2534 connection not available [com.romraider.io.j2534.api.J2534Exception: Error: [8] no devices available], trying serial connection...
166677 INFO [Thread-26] - Connected to: COM1
166677 INFO [Thread-26] - Serial connection initialised
168507 INFO [Thread-29] - Trying J2534 connection...
168509 INFO [Thread-29] - J2534 connection not available [com.romraider.io.j2534.api.J2534Exception: Error: [8] no devices available], trying serial connection...
168618 INFO [Thread-29] - Connected to: COM3
168618 INFO [Thread-29] - Serial connection initialised
168701 INFO [Thread-26] - Connection closed.
168701 INFO [Thread-26] - Error sending init: Parameter response must not be null or empty
169703 INFO [Thread-26] - Trying J2534 connection...
169703 INFO [Thread-26] - J2534 connection not available [com.romraider.io.j2534.api.J2534Exception: Error: [8] no devices available], trying serial connection...
170810 INFO [Thread-29] - ECU ID = 3D04EA4605
171747 INFO [Thread-26] - Connection closed.
171747 INFO [Thread-26] - Connection closed.
171747 INFO [Thread-26] - Error sending init: com.romraider.logger.ecu.exception.SerialCommunicationException: Port is currently in use: COM3
You start a connection on COM1 with Thread-26 and it fails. 2 seconds later you try a connection on COM3 with Thread-29 and it succeeds. BUT, Thread-26 continues and now tries to use COM3 which is in use by Thread-29. Thread-26 continues through the entire log to try and connect. It's like there are two Loggers running or two ECU comm threads running which I don't understand.
After a connection is made by Thread-29 I see the addition of the Defrost Switch, Battery Voltage and Engine Speed. The Logger runs in Fast Poll for 30 seconds then gets a bad response.
Code:
214506 DEBUG [Thread-29] - SSM Bad read response (read timeout):
214506 DEBUG [Thread-29] - Mode:1 ECU Response <--- 00000000000000000000
214506 ERROR [Thread-29] - Error occurred
com.romraider.logger.ecu.exception.InvalidResponseException: Invalid header. Expected: 80. Actual: 00.
214538 DEBUG [Thread-29] - SSM sending line break
214804 DEBUG [Thread-29] - SSM clearing line (stale data): 00
214960 INFO [Thread-29] - Connection closed.
214960 INFO [Thread-29] - TX Manager Stopped.
The connection is cleared and closed.
Then Thread-29 tries to re-establish comms, as does Thread-26.
Code:
214960 INFO [Thread-29] - J2534 connection not available [com.romraider.io.j2534.api.J2534Exception: Error: [8] no devices available], trying serial connection...
215024 INFO [Thread-26] - Trying J2534 connection...
215024 INFO [Thread-26] - J2534 connection not available [com.romraider.io.j2534.api.J2534Exception: Error: [8] no devices available], trying serial connection...
215055 INFO [Thread-29] - Connected to: COM3
215055 INFO [Thread-29] - Serial connection initialised
215055 DEBUG [Thread-29] - Ecu Init Request ---> 8010F001BF40
217012 INFO [Thread-26] - Connection closed.
217012 DEBUG [Thread-26] - Error sending init
com.romraider.logger.ecu.exception.NotConnectedException: com.romraider.logger.ecu.exception.SerialCommunicationException: Port is currently in use: COM3
217074 DEBUG [Thread-29] - Ecu Init Response <---
217262 INFO [Thread-29] - Connection closed.
217262 DEBUG [Thread-29] - Error sending init
Thread-29 sends an ECU Init but gets no response and closes the connection. This sequences goes on for 124 seconds then the Query Manager is stopped and the Logger is shutdown. Both Thread-26 & Thread-29 are terminated. Again it looks like two Loggers were running...?
Then 115 seconds later the Logger is started again (it appears as if you have started the Logger from the ECU Editor menu item) with debug already set to Trace level.
A single Thread is created and starts querying the ECU on COM3.
Code:
458491 DEBUG [Thread-8857] - QueryManager started.
458491 INFO [Thread-8857] - Trying J2534 connection...
458491 INFO [Thread-8857] - J2534 connection not available, trying serial connection...
458670 INFO [Thread-8857] - Connected to: COM3
458670 INFO [Thread-8857] - Serial connection initialised
458670 DEBUG [Thread-8857] - Ecu Init Request ---> 8010F001BF40
460825 DEBUG [Thread-8857] - Ecu Init Response <--- 80F01039FFA2100F3D04EA460573FAEB800A43FEAA00100070DE54F8B4000000000000000000DC0000451C000000000000000000800000000000000000D7
460825 INFO [Thread-8857] - ECU ID = 3D04EA4605
A profile is loaded containing Battery Voltage and Engine Speed.
Code:
461043 DEBUG [AWT-EventQueue-0] - Adding logger: [P17] Battery Voltage
461043 DEBUG [AWT-EventQueue-0] - Adding logger: [P8] Engine Speed
Queries go on for 30 seconds and then they stop.
Code:
490950 DEBUG [Thread-8857] - SSM Bad read response (read timeout):
490950 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 00000000000000000000
490950 ERROR [Thread-8857] - Error occurred
com.romraider.logger.ecu.exception.InvalidResponseException: Invalid header. Expected: 80. Actual: 00.
490981 DEBUG [Thread-8857] - SSM sending line break
491247 DEBUG [Thread-8857] - SSM clearing line (stale data): 00
491435 INFO [Thread-8857] - Connection closed.
491435 INFO [Thread-8857] - TX Manager Stopped.
Then the connection is initialized again and the ECU Init is sent, but there's no reply.
Code:
491435 INFO [Thread-8857] - Trying J2534 connection...
491435 INFO [Thread-8857] - J2534 connection not available, trying serial connection...
491546 INFO [Thread-8857] - Connected to: COM3
491546 INFO [Thread-8857] - Serial connection initialised
491546 DEBUG [Thread-8857] - Ecu Init Request ---> 8010F001BF40
493564 DEBUG [Thread-8857] - Ecu Init Response <---
494781 INFO [Thread-8857] - Connection closed.
494781 DEBUG [Thread-8857] - Error sending init
java.lang.IllegalArgumentException: Parameter response must not be null or empty
Finally!In the Trace data bytes I see that the Defrost Switch was off initially, but then became ON when your log file was created as the engine shut down. This would seem to be what triggers the Logger to write a new file.
| Raw Data | Battery | RPM | Byte 64 | Crankshaft | Camshaft | Defrost | Blower |
|---|
| 486938 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8AD0FE8D8E9 | 13.84 | 1018 | D8 | 1 | 1 | 0 | 1 |
| 486971 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8AD0FE8D8E9 | 13.84 | 1018 | D8 | 1 | 1 | 0 | 1 |
| 487001 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8AD0FE8D8E9 | 13.84 | 1018 | D8 | 1 | 1 | 0 | 1 |
| 487018 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8B30FDDF804 | 14.32 | 1015 | F8 | 1 | 1 | 1 | 1 |
| 487051 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8B30FDDF804 | 14.32 | 1015 | F8 | 1 | 1 | 1 | 1 |
| 487085 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8B30FDDF804 | 14.32 | 1015 | F8 | 1 | 1 | 1 | 1 |
| 487102 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8B00EF9F81C | 14.08 | 958 | F8 | 1 | 1 | 1 | 1 |
| 487134 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8B00EF9F81C | 14.08 | 958 | F8 | 1 | 1 | 1 | 1 |
| 487144 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8AC0DF4F812 | 13.76 | 893 | F8 | 1 | 1 | 1 | 1 |
| 487176 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8AC0DF4F812 | 13.76 | 893 | F8 | 1 | 1 | 1 | 1 |
| 487194 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8AC0DF4F812 | 13.76 | 893 | F8 | 1 | 1 | 1 | 1 |
| 487227 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A80CE0F8F9 | 13.44 | 824 | F8 | 1 | 1 | 1 | 1 |
| 487259 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A80CE0F8F9 | 13.44 | 824 | F8 | 1 | 1 | 1 | 1 |
| 487271 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A80CE0F8F9 | 13.44 | 824 | F8 | 1 | 1 | 1 | 1 |
| 487289 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A50BBAF8CF | 13.2 | 751 | F8 | 1 | 1 | 1 | 1 |
| 487322 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A50BBAF8CF | 13.2 | 751 | F8 | 1 | 1 | 1 | 1 |
| 487339 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A30B09F81C | 13.04 | 706 | F8 | 1 | 1 | 1 | 1 |
| 487373 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A30B09F81C | 13.04 | 706 | F8 | 1 | 1 | 1 | 1 |
| 487399 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A30B09F81C | 13.04 | 706 | F8 | 1 | 1 | 1 | 1 |
| 487417 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A20A7FF890 | 12.96 | 672 | F8 | 1 | 1 | 1 | 1 |
| 487450 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A20A7FF890 | 12.96 | 672 | F8 | 1 | 1 | 1 | 1 |
| 487467 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A10923F832 | 12.88 | 585 | F8 | 1 | 1 | 1 | 1 |
| 487501 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A10923F832 | 12.88 | 585 | F8 | 1 | 1 | 1 | 1 |
| 487518 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A10923F832 | 12.88 | 585 | F8 | 1 | 1 | 1 | 1 |
| 487544 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A10854F862 | 12.88 | 533 | F8 | 1 | 1 | 1 | 1 |
| 487576 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A10854F862 | 12.88 | 533 | F8 | 1 | 1 | 1 | 1 |
| 487593 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A10854F862 | 12.88 | 533 | F8 | 1 | 1 | 1 | 1 |
| 487623 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A1079AF8A7 | 12.88 | 487 | F8 | 1 | 1 | 1 | 1 |
| 487641 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A1079AF8A7 | 12.88 | 487 | F8 | 1 | 1 | 1 | 1 |
| 487671 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A106A7F8B3 | 12.88 | 426 | F8 | 1 | 1 | 1 | 1 |
| 487689 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A106A7F8B3 | 12.88 | 426 | F8 | 1 | 1 | 1 | 1 |
| 487722 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A106A7F8B3 | 12.88 | 426 | F8 | 1 | 1 | 1 | 1 |
| 487741 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A005B6F8C0 | 12.8 | 366 | F8 | 1 | 1 | 1 | 1 |
| 487767 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A005B6F8C0 | 12.8 | 366 | F8 | 1 | 1 | 1 | 1 |
| 487799 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A005B6B880 | 12.8 | 366 | B8 | 1 | 0 | 1 | 1 |
| 487817 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A005B6B880 | 12.8 | 366 | B8 | 1 | 0 | 1 | 1 |
| 487850 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A005B6B880 | 12.8 | 366 | B8 | 1 | 0 | 1 | 1 |
| 487869 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A0045DF866 | 12.8 | 279 | F8 | 1 | 1 | 1 | 1 |
| 487895 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A0045DF866 | 12.8 | 279 | F8 | 1 | 1 | 1 | 1 |
| 487913 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A0045DF866 | 12.8 | 279 | F8 | 1 | 1 | 1 | 1 |
| 487946 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A0045DF866 | 12.8 | 279 | F8 | 1 | 1 | 1 | 1 |
| 487975 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A0045DF866 | 12.8 | 279 | F8 | 1 | 1 | 1 | 1 |
| 487992 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A0045DF866 | 12.8 | 279 | F8 | 1 | 1 | 1 | 1 |
| 488023 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A0045DF866 | 12.8 | 279 | F8 | 1 | 1 | 1 | 1 |
| 488070 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A0045DF866 | 12.8 | 279 | F8 | 1 | 1 | 1 | 1 |
| 488073 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A00294F89B | 12.8 | 165 | F8 | 1 | 1 | 1 | 1 |
| 488091 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A00294F89B | 12.8 | 165 | F8 | 1 | 1 | 1 | 1 |
| 488140 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A00294F89B | 12.8 | 165 | F8 | 1 | 1 | 1 | 1 |
| 488171 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A00294F89B | 12.8 | 165 | F8 | 1 | 1 | 1 | 1 |
| 488189 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A00294F89B | 12.8 | 165 | F8 | 1 | 1 | 1 | 1 |
| 488215 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A00294F89B | 12.8 | 165 | F8 | 1 | 1 | 1 | 1 |
| 488246 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A00294F89B | 12.8 | 165 | F8 | 1 | 1 | 1 | 1 |
| 488248 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A00294F89B | 12.8 | 165 | F8 | 1 | 1 | 1 | 1 |
| 488266 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A00294B85B | 12.8 | 165 | B8 | 1 | 0 | 1 | 1 |
| 488299 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A00294B85B | 12.8 | 165 | B8 | 1 | 0 | 1 | 1 |
| 488331 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A00294B85B | 12.8 | 165 | B8 | 1 | 0 | 1 | 1 |
| 488342 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A00294B85B | 12.8 | 165 | B8 | 1 | 0 | 1 | 1 |
| 488374 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A00294B85B | 12.8 | 165 | B8 | 1 | 0 | 1 | 1 |
| 488392 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A0029438DB | 12.8 | 165 | 38 | 0 | 0 | 1 | 1 |
| 488423 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A0029438DB | 12.8 | 165 | 38 | 0 | 0 | 1 | 1 |
| 488440 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A0029438DB | 12.8 | 165 | 38 | 0 | 0 | 1 | 1 |
| 488473 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 488492 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 488519 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 488535 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 488567 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 488598 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 488616 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 488649 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 488667 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 488700 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 488732 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 488743 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 488775 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 488792 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 488825 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 488843 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 488876 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 488894 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 488917 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 488934 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 80F01005E8A000003845 | 12.8 | 0 | 38 | 0 | 0 | 1 | 1 |
| 490950 DEBUG [Thread-8857] - Mode:1 ECU Response <--- 0000000000000000000000 | 0 | 0 | | 0 | 0 | 0 | 0 |
Maybe you can try another experiment for me. Log the same parameters plus add the Ignition switch as well. I tried to replicate this on my own ECU and there is no change in the Defrost switch state, so that's why I can't see this file being created in me setup. Maybe the 32bit ECU has different logic with respect to switches or the BIU could be at fault here.