Fazecast / jSerialComm

Platform-independent serial port access for Java
GNU Lesser General Public License v3.0
1.35k stars 287 forks source link

why is closePort method synchronized on global lock #406

Closed rusefillc closed 2 years ago

rusefillc commented 2 years ago

SerialPort has three kinds of blocking/threading

  1. instance lock SerialPort.monitor
  2. global lock SerialPort.class.monitor
  3. thread join including join() without timeout

that's A LOT of complexity. Would it be possible to add code comments explaining the threading strategy of jSerialComm?

I am especially curious about https://github.com/rusefi/jSerialComm/commit/b52271c48cdc819b70ccb3960f97561a67954c7b which adds massive global lock without referencing specific use-cases of when that's beneficial or required.

if global lock is in fact needed I believe that the best practices are asking to reduce the protected section to the minimum. is the global lock protected section minimal at the moment? what are examples of entities/constraints which require global lock protection?

hedgecrw commented 2 years ago

Brief answers to your questions:

The global lock was added to the open and close methods because, under the hood in native code, these methods affect the global state/records of the serial ports along with the port enumeration methods getCommPorts() and getCommPort(String). Since the enumeration methods are synchronized class methods, it was necessary to also class-synchronize the open/close methods so that the library and ports did not get into weird states due to race conditions of users calling various combinations of these functions from different threads. (This was all based on bug reports, and the class synchronization fixed those bugs.) That being said, you are 100% correct that the critical section only involves the actual native function calls and not the entire open/close methods. As such, I've just checked in a fix which only class-synchronizes those specific native calls.

Regarding the join() method without a timeout, that's only partially true. The join without a timeout comes immediately after a timeout-enabled join fails, and the thread is then force-interrupted. Perhaps a better method would be to put the isAlive() and timed join() method calls in a loop so that it retries interrupting the thread if the first interrupt call fails, although I've never experienced this occurring in practice, nor are there any bug reports of that happening that I know of.

The bigger concern regarding what you posted on Issue #404, is that the native close method appears to be hanging and never returning. The only difference in the native close function between the current library version and 2.7.0 version (at least on Windows which it appears you are using) is a set of calls to cancel any awaiting I/O traffic on the serial ports before fully closing the port. I am guessing one of those might be hanging (although I'm not entirely sure why they would, but I have a suspicion on which call the culprit might be).

For starters, it appears you are testing using 2.8.0 which is several releases behind the current release of 2.9.0. Could you please retest using the latest version and verify that the problem still exists. If it does, would you be able to test a local beta JAR version if I send it to you with the suspecting offending call removed (as well as with the limited-scoped class synchronization)?

rusefillc commented 2 years ago

Yes, I use Win 7, 10 and 11

At first I've used 2.9.0 that's when I've noticed functionality degradation and found existing tickets which mention 2.7 as last working one, that's how I've ended up with 2.8.0 to confirm that my 2.9.0 problem or a similar problem has happened between 2.7 .0 and 2.8.0 see https://github.com/rusefi/rusefi/pull/3914

I would love to test a dirty with any fixes or extra logging or else!

hedgecrw commented 2 years ago

Gotcha - yes 2.8.0 was a MASSIVE heap of changes meant to deep dive and fundamentally fix a ton of issues that had cropped up and been patched prior to that, so a few regressions were inevitable given the millions of different serial devices, drivers, and OSs out there!

Thanks for agreeing to help with testing...it's the only way to verify some of these patches that I can't reproduce on my end. When you get a chance, please try out the following test version and see if it fixes your issue. If it doesn't, I'll make something with more explicit logging to figure out where exactly the hang is happening:

https://www.dropbox.com/t/0IwtlT6LT7uz0MS2

rusefillc commented 2 years ago

test FAILED

I 220214 203221.842 [AWT-EventQueue-0] PortDetector - Trying [COM3, COM31, COM32, COM33]
I 220214 203221.851 [AutoDetectPort1] SerialIoStream - Using com.fazecast.jSerialComm 2.9.1
I 220214 203221.851 [AutoDetectPort1] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM3
I 220214 203221.852 [AutoDetectPort2] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM31
I 220214 203221.852 [AutoDetectPort3] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM32
I 220214 203221.855 [AutoDetectPort4] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM33
I 220214 203221.892 [AutoDetectPort4] SerialAutoChecker - Got signature=rusEFI 2022.02.12.mre_f4.1768592053  from COM33
I 220214 203221.896 [AutoDetectPort4] SerialIoStream - COM33: Closing port...
I 220214 203222.420 [version checker] ConsoleUI - Reading from https://rusefi.com/console/versions.txt
I 220214 203222.422 [version checker] ConsoleUI - Server recommends java_console version 20171217 or newer
I 220214 203222.422 [version checker] ConsoleUI - Server recommends firmware 14892 or newer
I 220214 203226.846 [AWT-EventQueue-0] PortDetector - Now interrupting [Thread[AutoDetectPort1,5,main], Thread[AutoDetectPort2,5,main], Thread[AutoDetectPort3,5,main], Thread[AutoDetectPort4,5,main]]
I 220214 203226.846 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort1,5,main]
I 220214 203226.846 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort2,5,main]
I 220214 203226.846 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort3,5,main]
I 220214 203226.846 [AutoDetectPort1] SerialIoStream - COM3: Closing port...
I 220214 203226.846 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort4,5,main]
I 220214 203226.846 [AWT-EventQueue-0] PortDetector - Done interrupting!
D 220214 203226.847 [AWT-EventQueue-0] PortDetector - Found AutoDetectResult{serialPort='null', signature='null'} now stopping threads
I 220214 203227.015 [AutoDetectPort2] SerialIoStream - COM31: Closing port...
I 220214 203227.015 [AutoDetectPort2] SerialIoStream - COM31: Closed port.
I 220214 203227.047 [AWT-EventQueue-0] MessagesCentral - postMessage Launcher: Available port: COM3
I 220214 203227.049 [AWT-EventQueue-0] MessagesCentral - postMessage Launcher: Available port: COM31
I 220214 203227.049 [AWT-EventQueue-0] MessagesCentral - postMessage Launcher: Available port: COM32
I 220214 203227.050 [AWT-EventQueue-0] MessagesCentral - postMessage Launcher: Available port: COM33
I 220214 203227.074 [AutoDetectPort1] SerialIoStream - COM3: Closed port.
I 220214 203227.075 [AutoDetectPort4] SerialIoStream - COM33: Closed port.
I 220214 203227.075 [AutoDetectPort4] SerialAutoChecker - Propagating AutoDetectResult{serialPort='COM33', signature='rusEFI 2022.02.12.mre_f4.1768592053 '}
hedgecrw commented 2 years ago

Alright, please try the following and post the results:

https://www.dropbox.com/t/l0hUS11maqMhuwh7

This has line-by-line logging enabled so we can see exactly where the code is hanging.

rusefillc commented 2 years ago

I confirm new logging. I believe that functionality has degraded since yday version: we no longer receive "rusEFI 2022.02.12" response from device.

custom SerialPort.getVersion() would make my logs even better

baseline with yday version

I 220215 113946.146 [AWT-EventQueue-0] PortDetector - Trying [COM3, COM31, COM32, COM33]
I 220215 113946.151 [AutoDetectPort4] SerialIoStream - Using com.fazecast.jSerialComm 2.9.1
I 220215 113946.152 [AutoDetectPort4] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM33
I 220215 113946.152 [AutoDetectPort2] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM31
I 220215 113946.152 [AutoDetectPort3] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM32
I 220215 113946.152 [AutoDetectPort1] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM3
I 220215 113946.173 [AutoDetectPort4] SerialAutoChecker - Got signature=rusEFI 2022.02.12.mre_f4.1768592053  from COM33
I 220215 113946.173 [AutoDetectPort4] SerialIoStream - COM33: Closing port...
I 220215 113946.663 [version checker] ConsoleUI - Reading from https://rusefi.com/console/versions.txt
I 220215 113946.664 [version checker] ConsoleUI - Server recommends java_console version 20171217 or newer
I 220215 113946.664 [version checker] ConsoleUI - Server recommends firmware 14892 or newer
I 220215 113951.150 [AWT-EventQueue-0] PortDetector - Now interrupting [Thread[AutoDetectPort1,5,main], Thread[AutoDetectPort2,5,main], Thread[AutoDetectPort3,5,main], Thread[AutoDetectPort4,5,main]]
I 220215 113951.150 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort1,5,main]
I 220215 113951.150 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort2,5,main]
I 220215 113951.150 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort3,5,main]
I 220215 113951.150 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort4,5,main]
I 220215 113951.150 [AWT-EventQueue-0] PortDetector - Done interrupting!
D 220215 113951.151 [AWT-EventQueue-0] PortDetector - Found AutoDetectResult{serialPort='null', signature='null'} now stopping threads
I 220215 113951.361 [AutoDetectPort2] SerialIoStream - COM31: Closing port...
I 220215 113951.361 [AutoDetectPort2] SerialIoStream - COM31: Closed port.
I 220215 113951.387 [AutoDetectPort1] SerialIoStream - COM3: Closing port...
I 220215 113951.399 [AutoDetectPort4] SerialIoStream - COM33: Closed port.
I 220215 113951.399 [AutoDetectPort4] SerialAutoChecker - Propagating AutoDetectResult{serialPort='COM33', signature='rusEFI 2022.02.12.mre_f4.1768592053 '}
I 220215 113951.399 [AWT-EventQueue-0] MessagesCentral - postMessage Launcher: Available port: COM3
I 220215 113951.401 [AWT-EventQueue-0] MessagesCentral - postMessage Launcher: Available port: COM31
I 220215 113951.401 [AWT-EventQueue-0] MessagesCentral - postMessage Launcher: Available port: COM32
I 220215 113951.401 [AWT-EventQueue-0] MessagesCentral - postMessage Launcher: Available port: COM33
I 220215 113951.438 [AutoDetectPort1] SerialIoStream - COM3: Closed port.
Tue Feb 15 11:39:51 EST 2022: Error reading ../bundle_name.txt
I 220215 113951.678 [AWT-EventQueue-0] Launcher - Rendering available ports: [Auto Serial, COM3, COM31, COM32, COM33]
Tue Feb 15 11:39:51 EST 2022: Error reading ../bundle_name.txt
Tue Feb 15 11:39:51 EST 2022: Error reading ../bundle_name.txt
Tue Feb 15 11:39:51 EST 2022: Error reading ../bundle_name.txt

yday once again

I 220215 114052.661 [AWT-EventQueue-0] PortDetector - Trying [COM3, COM31, COM32, COM33]
I 220215 114052.668 [AutoDetectPort1] SerialIoStream - Using com.fazecast.jSerialComm 2.9.1
I 220215 114052.669 [AutoDetectPort1] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM3
I 220215 114052.669 [AutoDetectPort2] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM31
I 220215 114052.673 [AutoDetectPort3] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM32
I 220215 114052.682 [AutoDetectPort4] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM33
I 220215 114052.708 [AutoDetectPort4] SerialAutoChecker - Got signature=rusEFI 2022.02.12.mre_f4.1768592053  from COM33
I 220215 114052.708 [AutoDetectPort4] SerialIoStream - COM33: Closing port...
I 220215 114053.233 [version checker] ConsoleUI - Reading from https://rusefi.com/console/versions.txt
I 220215 114053.236 [version checker] ConsoleUI - Server recommends java_console version 20171217 or newer
I 220215 114053.236 [version checker] ConsoleUI - Server recommends firmware 14892 or newer

and yday for 3rd time to be sure

I 220215 114125.352 [AWT-EventQueue-0] PortDetector - Trying [COM3, COM31, COM32, COM33]
I 220215 114125.357 [AutoDetectPort1] SerialIoStream - Using com.fazecast.jSerialComm 2.9.1
I 220215 114125.357 [AutoDetectPort1] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM3
I 220215 114125.357 [AutoDetectPort3] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM32
I 220215 114125.357 [AutoDetectPort4] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM33
I 220215 114125.357 [AutoDetectPort2] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM31
I 220215 114125.379 [AutoDetectPort4] SerialAutoChecker - Got signature=rusEFI 2022.02.12.mre_f4.1768592053  from COM33
I 220215 114125.379 [AutoDetectPort4] SerialIoStream - COM33: Closing port...
I 220215 114125.889 [version checker] ConsoleUI - Reading from https://rusefi.com/console/versions.txt
I 220215 114125.893 [version checker] ConsoleUI - Server recommends java_console version 20171217 or newer
I 220215 114125.893 [version checker] ConsoleUI - Server recommends firmware 14892 or newer

now today version with more logs without response :(

I 220215 114202.396 [main] ConsoleUI - OS name: Windows 7
I 220215 114202.398 [main] ConsoleUI - OS version: 6.1
LazyFile: Not updating logs/README.html since looks to be the same content, new content size=171
Opening rusefi_tool.log
Console configuration from C:\Users\Huge\.rusEFI\console_properties.xml
I 220215 114202.721 [AWT-EventQueue-0] PortDetector - Trying [COM3, COM31, COM32, COM33]
I 220215 114202.725 [AutoDetectPort1] SerialIoStream - Using com.fazecast.jSerialComm 2.9.1
I 220215 114202.725 [AutoDetectPort1] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM3
I 220215 114202.725 [AutoDetectPort2] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM31
I 220215 114202.725 [AutoDetectPort3] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM32
I 220215 114202.725 [AutoDetectPort4] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM33
I 220215 114203.258 [version checker] ConsoleUI - Reading from https://rusefi.com/console/versions.txt
I 220215 114203.259 [version checker] ConsoleUI - Server recommends java_console version 20171217 or newer
I 220215 114203.259 [version checker] ConsoleUI - Server recommends firmware 14892 or newer
I 220215 114207.724 [AWT-EventQueue-0] PortDetector - Now interrupting [Thread[AutoDetectPort1,5,main], Thread[AutoDetectPort2,5,main], Thread[AutoDetectPort3,5,main], Thread[AutoDetectPort4,5,main]]
I 220215 114207.724 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort1,5,main]
I 220215 114207.724 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort2,5,main]
I 220215 114207.724 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort3,5,main]
I 220215 114207.724 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort4,5,main]
I 220215 114207.724 [AWT-EventQueue-0] PortDetector - Done interrupting!
D 220215 114207.725 [AWT-EventQueue-0] PortDetector - Found AutoDetectResult{serialPort='null', signature='null'} now stopping threads
I 220215 114207.945 [AutoDetectPort2] SerialIoStream - COM31: Closing port...
Java Code: closePort() called
Java Code: Calling serialEventListener.stopListening()
Java Code: serialEventListener.stopListening() called
Java Code: Returning from closePort()
I 220215 114207.946 [AutoDetectPort2] SerialIoStream - COM31: Closed port.
I 220215 114207.961 [AWT-EventQueue-0] MessagesCentral - postMessage Launcher: Available port: COM3
I 220215 114207.963 [AWT-EventQueue-0] MessagesCentral - postMessage Launcher: Available port: COM31
I 220215 114207.963 [AWT-EventQueue-0] MessagesCentral - postMessage Launcher: Available port: COM32
I 220215 114207.963 [AWT-EventQueue-0] MessagesCentral - postMessage Launcher: Available port: COM33
I 220215 114207.987 [AutoDetectPort1] SerialIoStream - COM3: Closing port...
Java Code: closePort() called
Java Code: Calling serialEventListener.stopListening()
Java Code: serialEventListener.stopListening() called
Java Code: Synchronizing on Java class
Java Code: Calling closePortNative()
I 220215 114207.996 [AutoDetectPort4] SerialIoStream - COM33: Closing port...
Java Code: closePort() called
Java Code: Calling serialEventListener.stopListening()
Java Code: serialEventListener.stopListening() called
Java Code: Synchronizing on Java class
Java Code: closePortNative() called
Java Code: Returning from closePort()
Java Code: Calling closePortNative()
I 220215 114208.023 [AutoDetectPort1] SerialIoStream - COM3: Closed port.
Java Code: closePortNative() called
Java Code: Returning from closePort()
I 220215 114208.023 [AutoDetectPort4] SerialIoStream - COM33: Closed port.
Tue Feb 15 11:42:08 EST 2022: Error reading ../bundle_name.txt
I 220215 114208.254 [AWT-EventQueue-0] Launcher - Rendering available ports: [Auto Serial, COM3, COM31, COM32, COM33]
Tue Feb 15 11:42:08 EST 2022: Error reading ../bundle_name.txt
Tue Feb 15 11:42:08 EST 2022: Error reading ../bundle_name.txt
Tue Feb 15 11:42:08 EST 2022: Error reading ../bundle_name.txt
I 220215 114209.159 [Ports Scanner] TcpConnector - Connection refused in getAvailablePorts(): simulator not running in 1000ms

Process finished with exit code -1
hedgecrw commented 2 years ago

Are you sure nothing has changed with the serial device on your end? The only difference between today's version and yesterday's is the addition of the print lines. Another problem I'm seeing is that the calls to closePortNative() are being logged but not any of the logs from the native code, so I'm wondering if somehow your Java application is still pulling in the old native library versions instead of the new ones.

rusefillc commented 2 years ago

Please note the timestamps, all four tests back to back within 6 minutes

I am replacing one jar file and restart my stuff via my IDE. Does that sound right for upgrade procedure?

I am happy to screen share you have my cell phone in the mail

hedgecrw commented 2 years ago

Yes, if you're already building your app using a local external JAR file, then it should be good to go by simply replacing it. From a quick Google search, it looks like some IDEs don't immediately output printf calls from native code unless they are explicitly flushed, so I just tried adding some flush calls after each printf in the native code. Please see if this works for outputting the native logs:

https://www.dropbox.com/t/9nWYLNQ8hvTEapue

(And if you're still not receiving the string response from your device, please retest using yesterday's version again just to verify that the device is still responding.)

rusefillc commented 2 years ago

ohh looks like I really should unplug and plug USB back between jar files or runs, something is not perfect there we can revisit later :)

latest version with good read from controller but bad close

I 220215 123802.043 [AWT-EventQueue-0] PortDetector - Trying [COM3, COM31, COM32, COM33]
I 220215 123802.048 [AutoDetectPort2] SerialIoStream - Using com.fazecast.jSerialComm 2.9.1-printlog2
I 220215 123802.048 [AutoDetectPort2] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM31
I 220215 123802.048 [AutoDetectPort1] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM3
I 220215 123802.049 [AutoDetectPort3] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM32
I 220215 123802.053 [AutoDetectPort4] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM33
I 220215 123802.088 [AutoDetectPort4] SerialAutoChecker - Got signature=rusEFI 2022.02.12.mre_f4.1768592053  from COM33
I 220215 123802.088 [AutoDetectPort4] SerialIoStream - COM33: Closing port...
Java Code [COM33]: closePort() called
Java Code [COM33]: Calling serialEventListener.stopListening()
Java Code [COM33]: serialEventListener.stopListening() called
Java Code [COM33]: Synchronizing on Java class
I 220215 123802.626 [version checker] ConsoleUI - Reading from https://rusefi.com/console/versions.txt
I 220215 123802.630 [version checker] ConsoleUI - Server recommends java_console version 20171217 or newer
I 220215 123802.630 [version checker] ConsoleUI - Server recommends firmware 14892 or newer
I 220215 123807.047 [AWT-EventQueue-0] PortDetector - Now interrupting [Thread[AutoDetectPort1,5,main], Thread[AutoDetectPort2,5,main], Thread[AutoDetectPort3,5,main], Thread[AutoDetectPort4,5,main]]
I 220215 123807.047 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort1,5,main]
I 220215 123807.047 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort2,5,main]
I 220215 123807.047 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort3,5,main]
I 220215 123807.048 [AutoDetectPort1] SerialIoStream - COM3: Closing port...
Java Code [COM3]: closePort() called
I 220215 123807.048 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort4,5,main]
Java Code [COM3]: Calling serialEventListener.stopListening()
I 220215 123807.048 [AWT-EventQueue-0] PortDetector - Done interrupting!
Java Code [COM3]: serialEventListener.stopListening() called
Java Code [COM3]: Synchronizing on Java class
D 220215 123807.050 [AWT-EventQueue-0] PortDetector - Found AutoDetectResult{serialPort='null', signature='null'} now stopping threads
I 220215 123807.289 [AutoDetectPort2] SerialIoStream - COM31: Closing port...
Java Code [COM31]: closePort() called
Java Code [COM31]: Calling serialEventListener.stopListening()
Java Code [COM31]: serialEventListener.stopListening() called
Java Code [COM31]: Returning from closePort()
I 220215 123807.289 [AutoDetectPort2] SerialIoStream - COM31: Closed port.
Java Code [COM3]: Calling closePortNative()
Native Code: Setting port timeouts
Native Code: Purging port
Native Code: Canceling port IO operations
Native Code: Removing all port event listening flags
Native Code: Calling CloseHandle()
I 220215 123807.309 [AWT-EventQueue-0] MessagesCentral - postMessage Launcher: Available port: COM3
I 220215 123807.310 [AWT-EventQueue-0] MessagesCentral - postMessage Launcher: Available port: COM31
I 220215 123807.310 [AWT-EventQueue-0] MessagesCentral - postMessage Launcher: Available port: COM32
I 220215 123807.310 [AWT-EventQueue-0] MessagesCentral - postMessage Launcher: Available port: COM33
Native Code: CloseHandle() called
Java Code [COM3]: closePortNative() called
Java Code [COM3]: Returning from closePort()
I 220215 123807.336 [AutoDetectPort1] SerialIoStream - COM3: Closed port.
Java Code [COM33]: Calling closePortNative()
Native Code: Setting port timeouts
Native Code: Purging port
Native Code: Canceling port IO operations
Native Code: Removing all port event listening flags
Native Code: Calling CloseHandle()
Native Code: CloseHandle() called
Java Code [COM33]: closePortNative() called
Java Code [COM33]: Returning from closePort()
I 220215 123807.336 [AutoDetectPort4] SerialIoStream - COM33: Closed port.
I 220215 123807.336 [AutoDetectPort4] SerialAutoChecker - Propagating AutoDetectResult{serialPort='COM33', signature='rusEFI 2022.02.12.mre_f4.1768592053 '}
Tue Feb 15 12:38:07 EST 2022: Error reading ../bundle_name.txt
I 220215 123807.552 [AWT-EventQueue-0] Launcher - Rendering available ports: [Auto Serial, COM3, COM31, COM32, COM33]
hedgecrw commented 2 years ago

Verrrry interesting....so it's not actually hanging in the native code at all. It's hanging waiting to acquire the lock to enter the native code in the closePort() call. Which means that one of your threads is actually hanging in the native portion of the openPort() call until your timer expires and interrupts it. Let me move the global lock out of Java and into the native code so that I can only protect the very specific portions that alter global state variables. This should allow the rest of your threads to run as expected. I'll post back when I have that change implemented.

sprut666666 commented 2 years ago

@hedgecrw

Same problem MacBook M1

Java Code [tty.usbserial-0001]: closePort() called Java Code [tty.usbserial-0001]: Calling serialEventListener.stopListening() Java Code [tty.usbserial-0001]: serialEventListener.stopListening() called Java Code [tty.usbserial-0001]: Synchronizing on Java class Java Code [tty.usbserial-0001]: Calling closePortNative() Java Code [tty.usbserial-0001]: closePortNative() called Java Code [tty.usbserial-0001]: Returning from closePort()

hedgecrw commented 2 years ago

@sprut666666, what is the issue you are seeing? The output you posted looks correct and as expected.

sprut666666 commented 2 years ago

@hedgecrw There is a lock that does not allow the application to close correctly. 2.7.0 - Everything is fine <=2.8.0 - lock This behavior was observed on raspberry pi on version 2.8.5, in version 2.9.0 everything began to work correctly, I think after this change Allow SIGINT to reach top-level Java application for graceful shutdown

hedgecrw commented 2 years ago

Oh yes, if your issue was already resolved in 2.9.0, then it's unrelated to this thread.

hedgecrw commented 2 years ago

@rusefillc, please test the following version. This has removed all Java-side class synchronization and moved locks to be native-side, only covering the few code lines which alter global resources:

https://www.dropbox.com/t/6hoybASQYqpJOtPY

sprut666666 commented 2 years ago

Oh yes, if your issue was already resolved in 2.9.0, then it's unrelated to this thread.

2.9.0 - solved the problem for Raspberry 2.9.0 - problem still exists for MacBook M1

hedgecrw commented 2 years ago

@sprut666666, please test the version I just posted above and see if the problem persists on MacBook.

sprut666666 commented 2 years ago

@hedgecrw The problem persists, but I found the cause, but I don't know how to describe it...) if run project in gradle (intellij idea) with 'run' parameter then it can't be stopped.

rusefillc commented 2 years ago

@hedgecrw @sprut666666 is it time to split two separate discussions into two separate tickets?

sprut666666 commented 2 years ago

Yes, the issues are unrelated. I'll start a separate issue.

hedgecrw commented 2 years ago

@rusefillc, did the changes removing the Java-side locks resolve this issue for you?

rusefillc commented 2 years ago

my bad @hedgecrw I've missed https://github.com/Fazecast/jSerialComm/issues/406#issuecomment-1040727281 let me test now

rusefillc commented 2 years ago

@hedgecrw test failed, still too many seconds to close COM33

I 220216 131912.007 [AWT-EventQueue-0] PortDetector - Trying [COM3, COM31, COM32, COM33]
I 220216 131912.011 [AutoDetectPort4] SerialIoStream - Using com.fazecast.jSerialComm 2.9.1-nativemutex
I 220216 131912.011 [AutoDetectPort4] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM33
I 220216 131912.011 [AutoDetectPort3] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM32
I 220216 131912.011 [AutoDetectPort2] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM31
I 220216 131912.011 [AutoDetectPort1] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM3
I 220216 131912.021 [AutoDetectPort4] SerialAutoChecker - Got signature=rusEFI 2022.02.12.mre_f4.1768592053  from COM33
I 220216 131912.021 [AutoDetectPort4] SerialIoStream - COM33: Closing port...
I 220216 131912.525 [version checker] ConsoleUI - Reading from https://rusefi.com/console/versions.txt
I 220216 131912.529 [version checker] ConsoleUI - Server recommends java_console version 20171217 or newer
I 220216 131912.530 [version checker] ConsoleUI - Server recommends firmware 14892 or newer
I 220216 131917.009 [AWT-EventQueue-0] PortDetector - Now interrupting [Thread[AutoDetectPort1,5,main], Thread[AutoDetectPort2,5,main], Thread[AutoDetectPort3,5,main], Thread[AutoDetectPort4,5,main]]
I 220216 131917.009 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort1,5,main]
I 220216 131917.009 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort2,5,main]
I 220216 131917.009 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort3,5,main]
I 220216 131917.009 [AutoDetectPort1] SerialIoStream - COM3: Closing port...
I 220216 131917.009 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort4,5,main]
I 220216 131917.009 [AWT-EventQueue-0] PortDetector - Done interrupting!
D 220216 131917.010 [AWT-EventQueue-0] PortDetector - Found AutoDetectResult{serialPort='null', signature='null'} now stopping threads
I 220216 131917.163 [AutoDetectPort2] SerialIoStream - COM31: Closing port...
I 220216 131917.163 [AutoDetectPort2] SerialIoStream - COM31: Closed port.
I 220216 131917.163 [AutoDetectPort4] SerialIoStream - COM33: Closed port.
I 220216 131917.164 [AutoDetectPort4] SerialAutoChecker - Propagating AutoDetectResult{serialPort='COM33', signature='rusEFI 2022.02.12.mre_f4.1768592053 '}
I 220216 131917.191 [AutoDetectPort1] SerialIoStream - COM3: Closed port.
I 220216 131917.192 [AWT-EventQueue-0] MessagesCentral - postMessage Launcher: Available port: COM3
I 220216 131917.193 [AWT-EventQueue-0] MessagesCentral - postMessage Launcher: Available port: COM31
hedgecrw commented 2 years ago

So weird...the only OS-specific call that was still protected was the native call to CreateFile to open the port (which I wouldn't expect to hang unless there's a problem with the underlying driver). In any case, let's try to kill two birds with one stone. I've removed ALL OS-specific calls from the critical section, leaving only assignment or reading from global state, so there should be no way for threads to block one another any more for more than a couple nanoseconds. I've also added a whole ton of native code logging to both open and close port operations to track down where any further issues are occurring (which hopefully will be none):

https://www.dropbox.com/t/75SarQc7JO5C92Wm

rusefillc commented 2 years ago

test passed!

I 220216 145714.728 [main] ConsoleUI - OS name: Windows 7
I 220216 145714.730 [main] ConsoleUI - OS version: 6.1
LazyFile: Not updating logs/README.html since looks to be the same content, new content size=171
Opening rusefi_tool.log
Console configuration from C:\Users\Huge\.rusEFI\console_properties.xml
I 220216 145715.114 [AWT-EventQueue-0] PortDetector - Trying [COM3, COM31, COM32, COM33]
I 220216 145715.119 [AutoDetectPort1] SerialIoStream - Using com.fazecast.jSerialComm 2.9.1-mutexlog
I 220216 145715.120 [AutoDetectPort1] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM3
I 220216 145715.120 [AutoDetectPort4] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM33
I 220216 145715.120 [AutoDetectPort3] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM32
I 220216 145715.121 [AutoDetectPort2] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM31
[COM?]: In openPortNative()
[COM?]: In openPortNative()
[COM?]: In openPortNative()
[\\.\COM3]: Entering openPortNative critical section #1
[\\.\COM33]: Entering openPortNative critical section #1
[\\.\COM3]: Leaving openPortNative critical section #1
[\\.\COM3]: Attempting to reduce port latency
[\\.\COM33]: Leaving openPortNative critical section #1
[\\.\COM33]: Attempting to reduce port latency
[\\.\COM31]: Entering openPortNative critical section #1
[\\.\COM31]: Leaving openPortNative critical section #1
[\\.\COM33]: Attempting to open port
[\\.\COM31]: Attempting to reduce port latency
[COM?]: In openPortNative()
[\\.\COM33]: Entering openPortNative critical section #2
[\\.\COM32]: Entering openPortNative critical section #1
[\\.\COM33]: Leaving openPortNative critical section #2
[\\.\COM33]: Configuring port
[\\.\COM31]: Attempting to open port
[\\.\COM32]: Leaving openPortNative critical section #1
[\\.\COM32]: Attempting to reduce port latency
[\\.\COM3]: Attempting to open port
[\\.\COM32]: Attempting to open port
[\\.\COM32]: Entering openPortNative critical section #2
[\\.\COM32]: Leaving openPortNative critical section #2
[\\.\COM32]: Configuring port
[\\.\COM32]: Leaving openPortNative()
[\\.\COM33]: Leaving openPortNative()
I 220216 145715.133 [AutoDetectPort4] SerialAutoChecker - Got signature=rusEFI 2022.02.12.mre_f4.1768592053  from COM33
I 220216 145715.133 [AutoDetectPort4] SerialIoStream - COM33: Closing port...
[COM?]: In closePortNative()
[\\.\COM33]: Purging all active port operations
[\\.\COM33]: Closing port
[\\.\COM33]: Entering closePortNative critical section #1
[\\.\COM33]: Leaving closePortNative critical section #1
I 220216 145715.133 [AutoDetectPort4] SerialIoStream - COM33: Closed port.
I 220216 145715.134 [AutoDetectPort4] SerialAutoChecker - Propagating AutoDetectResult{serialPort='COM33', signature='rusEFI 2022.02.12.mre_f4.1768592053 '}
I 220216 145715.134 [AWT-EventQueue-0] PortDetector - Now interrupting [Thread[AutoDetectPort1,5,main], Thread[AutoDetectPort2,5,main], Thread[AutoDetectPort3,5,main], Thread[AutoDetectPort4,5,]]
I 220216 145715.134 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort1,5,main]
I 220216 145715.134 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort2,5,main]
I 220216 145715.134 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort3,5,main]
I 220216 145715.134 [AWT-EventQueue-0] PortDetector - Interrupting Thread[AutoDetectPort4,5,]
I 220216 145715.134 [AWT-EventQueue-0] PortDetector - Done interrupting!
D 220216 145715.134 [AWT-EventQueue-0] PortDetector - Found AutoDetectResult{serialPort='COM33', signature='rusEFI 2022.02.12.mre_f4.1768592053 '} now stopping threads
communicationThread lookup DONE
[\\.\COM3]: Entering openPortNative critical section #2
[\\.\COM3]: Leaving openPortNative critical section #2
[\\.\COM3]: Configuring port
[\\.\COM3]: Leaving openPortNative()
I 220216 145715.147 [AutoDetectPort1] SerialIoStream - COM3: Closing port...
[COM?]: In closePortNative()
[\\.\COM3]: Purging all active port operations
[\\.\COM3]: Closing port
class com.rusefi.io.CommandQueue: SerialIO started
[\\.\COM3]: Entering closePortNative critical section #1
[\\.\COM3]: Leaving closePortNative critical section #1
I 220216 145715.174 [AutoDetectPort1] SerialIoStream - COM3: Closed port.
I 220216 145715.796 [version checker] ConsoleUI - Reading from https://rusefi.com/console/versions.txt
I 220216 145715.798 [version checker] ConsoleUI - Server recommends java_console version 20171217 or newer
I 220216 145715.798 [version checker] ConsoleUI - Server recommends firmware 14892 or newer
Wed Feb 16 14:57:16 EST 2022: Error reading ../bundle_name.txt
I 220216 145716.096 [AWT-EventQueue-0] ConsoleUI - Console 20220213
I 220216 145716.098 [AWT-EventQueue-0] ConsoleUI - Hardware: F4
I 220216 145716.098 [AWT-EventQueue-0] LinkManager - LinkManager: Starting COM33
Zoom setValue 1.0
ANTLR Tool version 4.5 used for code generation does not match the current runtime version 4.9.3
ANTLR Tool version 4.5 used for code generation does not match the current runtime version 4.9.3
line 1:23 no viable alternative at input 'high_pressure_fuel_pump.'
line 1:14 no viable alternative at input 'injector_model.'
line 1:14 no viable alternative at input 'launch_control.'
line 1:11 no viable alternative at input 'fan_control.'
line 1:9 no viable alternative at input 'fuel_pump.'
line 1:10 no viable alternative at input 'main_relay.'
line 1:6 no viable alternative at input 'engine.'
line 1:16 no viable alternative at input 'accel_enrichment.'
line 1:15 no viable alternative at input 'trigger_central.'
line 1:15 no viable alternative at input 'trigger_decoder.'
line 1:9 no viable alternative at input 'wall_fuel.'
line 1:11 no viable alternative at input 'idle_thread.'
I 220216 145717.705 [AWT-EventQueue-0] MessagesCentral - postMessage ConsoleUI: COMPOSITE_OFF_RPM=10000
I 220216 145717.708 [AWT-EventQueue-0] AuthTokenPanel - Auth token from settings: 7590ebef-c5fc-4427-9f22-cafff43f8602
I 220216 145717.724 [AWT-EventQueue-0] AuthTokenPanel - Ignoring java.awt.datatransfer.UnsupportedFlavorException: Unicode String
Saved settings to C:\Users\Huge\.rusEFI\console_properties.xml
I 220216 145718.478 [AWT-EventQueue-0] Launcher - onWindowOpened
I 220216 145718.481 [AWT-EventQueue-0] StreamConnector - StreamConnector: connecting
I 220216 145718.481 [AWT-EventQueue-0] StreamConnector - scheduleOpening
I 220216 145718.482 [communication executor1] StreamConnector - scheduleOpening>openPort
class com.rusefi.io.LinkManager$5: Opening port: COM33
I 220216 145718.483 [communication executor1] BufferedSerialIoStream - [BufferedSerialIoStream] openPort COM33
[COM?]: In openPortNative()
[\\.\COM33]: Entering openPortNative critical section #1
[\\.\COM33]: Leaving openPortNative critical section #1
[\\.\COM33]: Attempting to reduce port latency
[\\.\COM33]: Attempting to open port
[\\.\COM33]: Entering openPortNative critical section #2
[\\.\COM33]: Leaving openPortNative critical section #2
[\\.\COM33]: Configuring port
[\\.\COM33]: Leaving openPortNative()
I 220216 145718.495 [communication executor1] BinaryProtocol - Got rusEFI 2022.02.12.mre_f4.1768592053  signature
I 220216 145718.502 [communication executor1] BinaryProtocol - current_configuration.rusefi_binary Local cache CRC 957d214e

I 220216 145718.506 [communication executor1] BinaryProtocol - rusEFI says tune CRC32 0x474279d3 1195538899

I 220216 145718.506 [communication executor1] BinaryProtocol - rusEFI says tune CRC16 0x79d3 31187

I 220216 145718.506 [communication executor1] BinaryProtocol - Reading from controller...
Saving 21012 bytes of configuration into current_configuration.rusefi_binarySaved to current_configuration.rusefi_binary
I 220216 145718.600 [communication executor1] IniFileModel - Searching for rusefi*.ini in ../firmware/tunerstudio/generated
I 220216 145718.601 [communication executor1] IniFileModel - Reading ../firmware/tunerstudio/generated\rusefi.ini
I 220216 145718.681 [communication executor1] IniFileModel - Section [SettingGroups]
I 220216 145718.681 [communication executor1] IniFileModel - Section [MegaTune]
I 220216 145718.681 [communication executor1] IniFileModel - Section [TunerStudio]
I 220216 145718.681 [communication executor1] IniFileModel - Section [Constants]
I 220216 145718.740 [communication executor1] IniFileModel - Section [Tuning]
I 220216 145718.740 [communication executor1] IniFileModel - Section [LoggerDefinition]
hedgecrw commented 2 years ago

Finally! I'll go ahead and check in this fix. It seems like whatever is on your COM31 port just hangs when trying to open. Not sure what that's about, but there's nothing I can do about it from within this library.

sprut666666 commented 2 years ago

So weird...the only OS-specific call that was still protected was the native call to CreateFile to open the port (which I wouldn't expect to hang unless there's a problem with the underlying driver). In any case, let's try to kill two birds with one stone. I've removed ALL OS-specific calls from the critical section, leaving only assignment or reading from global state, so there should be no way for threads to block one another any more for more than a couple nanoseconds. I've also added a whole ton of native code logging to both open and close port operations to track down where any further issues are occurring (which hopefully will be none):

https://www.dropbox.com/t/75SarQc7JO5C92Wm

Great job, my problem for MacOs M1 is solved.

The only difference from 2.7.0, the application is closed: jSerialComm-2.9.1-mutexlog.jar - 5-7 seconds jSerialComm:2.7.0 - 1-2 seconds.

hedgecrw commented 2 years ago

@sprut666666, glad you're able to close on MacOS now, but the time required for closing is concerning and not as expected. I'm going to open a new issue to track that: #Issue 409.

hedgecrw commented 2 years ago

Closing this as resolved with today's release v2.9.1.