search

nyholku / purejavacomm

Pure Java implementation of JavaComm SerialPort
http://www.sparetimelabs.com/purejavacomm/index.html
BSD 3-Clause "New" or "Revised" License
366 stars 146 forks source link

jtermios.windows.JTermiosImpl$Fail after update from v0.0.22 to v0.0.24 #57

Closed malkavi closed 9 years ago

malkavi commented 9 years ago

Hi, There is my first error report since I start using the library. I have updated from 0.0.22 to 24 without changing anything. This is my code, the Exception is raised in the line serialPort.notifyOnDataAvailable(true); if I ignore it raised later this

Exception in thread "Thread-8" purejavacomm.PureJavaIllegalStateException: File descriptor is -1 < 0, maybe closed by previous error condition

The code:

                try {
            serialPort = (SerialPort) portId.open("SimpleReadApp", 1000);
        } catch (PortInUseException e) {
            System.out.println("Puerto " + portId.getName() + " en uso.");
            com.incrementarError();
        }
        if (com.getError() > 0) {
            return EN_USO; //is in use
        } else {
            try {
                inputStream = serialPort.getInputStream();
                outputStream = serialPort.getOutputStream();
            } catch (IOException e) {
                try {
                    inputStream.close();
                    outputStream.close();
                } catch (IOException e1) {
                }
                serialPort.close();
                return ERROR;
            }
            serialPort.setOutputBufferSize(tamMAXColaWrite);
            if (TRAZAS) {
                System.out.println("tamaño buffer " + serialPort.getOutputBufferSize());
            }

            try {
                serialPort.addEventListener(this);
            } catch (TooManyListenersException e) {
                try {
                    inputStream.close();
                    outputStream.close();
                } catch (IOException e1) {
                }
                serialPort.close();
                return ERROR;
            }

            serialPort.notifyOnDataAvailable(true);

The exception:

COM82 a 19200
PureJavaComm: 0.0.24 de SpareTimeLabs
jtermios.windows.JTermiosImpl$Fail
    at jtermios.windows.JTermiosImpl$Port.fail(JTermiosImpl.java:100)
    at jtermios.windows.JTermiosImpl.select(JTermiosImpl.java:842)
    at jtermios.JTermios.select(JTermios.java:439)
    at purejavacomm.PureJavaSerialPort$3.run(PureJavaSerialPort.java:1226)
    at java.lang.Thread.run(Thread.java:745)
nyholku commented 9 years ago

Thanks for the report, I'll try the get the originator of the mods to have a look at it.

malkavi commented 9 years ago

Sorry, I forgot to say that I'm using Windows (7 and 10).

PeteSL commented 9 years ago

Ok, I am going to play devil's advocate. Line 1226 in PureJavaSerialPort is: n = select(m_FD + 1, rset, wset, null, m_HaveNudgePipe ? null : timeout); Why m_FD + 1 when everything else is m_FD? The fail is occurring coming out of the WaitMultipleObjects and I think it is a legitimate error if it is looking at the wrong File Discriptor. My testing did not use the AddEventListener so I am guessing this code was never called. Can we test with that changed to m_FD instead of m_FD + 1 and see if that works?

malkavi commented 9 years ago

The error now seems to be worse. XD If I remember correctly, the usage of the select was correct, at least in c. (file descriptor +1)

GRAVE: null
java.io.IOException
    at purejavacomm.PureJavaSerialPort$1.write(PureJavaSerialPort.java:646)
    at purejavacomm.PureJavaSerialPort$1.write(PureJavaSerialPort.java:657)
    at com.mirakonta.comunicaciones.PuertoSerie.escribirSerie(PuertoSerie.java:242)
    at mk.maestro.com.Comunicacion.escribirCon(Comunicacion.java:150)
    at com.mirakonta.lib.maestro.Protocolo.a(Unknown Source)
    at com.mirakonta.lib.maestro.Protocolo.faseInicial(Unknown Source)
    at mk.maestro.gui.fx.cont.pet.VersionCont$3.run(VersionCont.java:149)
    at java.lang.Thread.run(Thread.java:745)

Exception in thread "Thread-6" purejavacomm.PureJavaIllegalStateException: File descriptor is -1 < 0, maybe closed by previous error condition
    at purejavacomm.PureJavaSerialPort.failWithIllegalStateException(PureJavaSerialPort.java:1289)
    at purejavacomm.PureJavaSerialPort.checkState(PureJavaSerialPort.java:1294)
    at purejavacomm.PureJavaSerialPort.access$0(PureJavaSerialPort.java:1292)
    at purejavacomm.PureJavaSerialPort$1.write(PureJavaSerialPort.java:631)
    at purejavacomm.PureJavaSerialPort$1.write(PureJavaSerialPort.java:657)
    at com.mirakonta.comunicaciones.PuertoSerie.escribirSerie(PuertoSerie.java:242)
    at mk.maestro.com.Comunicacion.escribirCon(Comunicacion.java:150)
    at com.mirakonta.lib.maestro.Protocolo.a(Unknown Source)
    at com.mirakonta.lib.maestro.Protocolo.faseInicial(Unknown Source)
    at mk.maestro.gui.fx.cont.pet.VersionCont$3.run(VersionCont.java:149)
    at java.lang.Thread.run(Thread.java:745)
nyholku commented 9 years ago

Yeah, select requires n+1. See 'man select':

"nfds is the highest-numbered file descriptor in any of the three sets, plus 1."

This is something else but Pete who did the changes is looking at the code as we 'speak'.

PeteSL commented 9 years ago

Ok, change it back. My tests go through line 886 for the select. I know that before I went to using the Native.GetLastError() instead of a direct C call, that call to WaitMultipleObjects would fail for no understandable reason (would return 0 instead of ERROR_IO_PENDING). I didn't alter the select code at all in this version. What has changed is moving the WaitMultipleObjects out of the Direct Mapping because it uses an array of Handles which is not allowed in Direct Mapping. Everything else is the same. I will look further...

PeteSL commented 9 years ago

Oh yeah, I am the author of the mods.

PeteSL commented 9 years ago

The difference between the 2 calls is your select call uses a write fdset so I will look at that piece to see if something is askew...

PeteSL commented 9 years ago

My bad, haven't had my first cup of coffee yet... This is out of WaitCommEvent which was also where I saw a problem. I am going to look a the definition of WaitCommEvent to make sure we don't have another issue.

PeteSL commented 9 years ago

The WaitCommEvent definition looks correct. Could you set -Dpurejavacomm.loglevel=9 in your java command line and then let us see the logging before and after the WaitCommEvent? What I am looking for is the actual code returned by GetLastError and also see the values being passed to WaitCommEvent (the File Descriptor should be the same as what was passed to SetCommMask). Also, look early on to ensure that a proper handle was created for m_SelOV. In the mean time, I am still digging deep.

malkavi commented 9 years ago

Sorry for the long post. I have enabled the log and try again.

COM82 a 19200
PureJavaComm: 0.0.24 de SpareTimeLabs
log: 750641,class jtermios.windows.JTermiosImpl line 1120, thread id 17, Thread-6, > QueryDosDeviceA(null, [B@18d6e02, 16384)
log: 750642,class jtermios.windows.JTermiosImpl line 1120, thread id 17, Thread-6, < QueryDosDeviceA(null, [B@18d6e02, 16384) => 15372
log: 750648,class purejavacomm.PureJavaSerialPort line 1087, thread id 17, Thread-6, > open('COM82',00020006)
log: 750653,class jtermios.windows.JTermiosImpl$Port line 140, thread id 17, Thread-6, > CreateFileA(\\.\COM82, 0xC0000000, 0x00000000, null, 0x00000003, 0x40000000,null)
log: 750705,class jtermios.windows.JTermiosImpl$Port line 140, thread id 17, Thread-6, < CreateFileA(\\.\COM82, 0xC0000000, 0x00000000, null, 0x00000003, 0x40000000,null) => native@0x480
log: 750705,class jtermios.windows.JTermiosImpl$Port line 150, thread id 17, Thread-6, > SetCommTimeouts(native@0x480, 2048, 2048)
log: 750706,class jtermios.windows.JTermiosImpl$Port line 150, thread id 17, Thread-6, < SetCommTimeouts(native@0x480, 2048, 2048) => true
log: 750706,class jtermios.windows.JTermiosImpl line 623, thread id 17, Thread-6, > GetCommState(native@0x480, [BaudRate 0 fFlags 0000 wReserved 0 XonLim 0 XoffLim 0 ByteSize 0 Parity 0 StopBits 0 XonChar 00 XoffChar 00 ErrorChar 00 EofChar 00 EvtChar 00 wReserved1 0])
log: 750709,class jtermios.windows.JTermiosImpl line 623, thread id 17, Thread-6, < GetCommState(native@0x480, [BaudRate 9600 fFlags 0001 wReserved 0 XonLim 2048 XoffLim 512 ByteSize 8 Parity 0 StopBits 0 XonChar 11 XoffChar 13 ErrorChar 00 EofChar 00 EvtChar 0A wReserved1 0]) => true
log: 750709,class jtermios.windows.JTermiosImpl line 701, thread id 17, Thread-6, > SetCommState(native@0x480, [BaudRate 9600 fFlags 0001 wReserved 0 XonLim 2048 XoffLim 512 ByteSize 8 Parity 0 StopBits 0 XonChar 00 XoffChar 00 ErrorChar 00 EofChar 00 EvtChar 0A wReserved1 0])
log: 750724,class jtermios.windows.JTermiosImpl line 701, thread id 17, Thread-6, < SetCommState(native@0x480, [BaudRate 9600 fFlags 0001 wReserved 0 XonLim 2048 XoffLim 512 ByteSize 8 Parity 0 StopBits 0 XonChar 00 XoffChar 00 ErrorChar 00 EofChar 00 EvtChar 0A wReserved1 0]) => true
log: 750724,class jtermios.windows.JTermiosImpl line 746, thread id 17, Thread-6, > SetCommTimeouts(native@0x480, [ReadIntervalTimeout -1 ReadTotalTimeoutMultiplier 0 ReadTotalTimeoutConstant 0 WriteTotalTimeoutMultiplier 0 WriteTotalTimeoutConstant 0])
log: 750725,class jtermios.windows.JTermiosImpl line 746, thread id 17, Thread-6, < SetCommTimeouts(native@0x480, [ReadIntervalTimeout -1 ReadTotalTimeoutMultiplier 0 ReadTotalTimeoutConstant 0 WriteTotalTimeoutMultiplier 0 WriteTotalTimeoutConstant 0]) => true
log: 750725,class jtermios.windows.JTermiosImpl$Port line 158, thread id 17, Thread-6, vmin 0 vtime 0 ReadIntervalTimeout -1 ReadTotalTimeoutConstant 0 ReadTotalTimeoutMultiplier 0
log: 750725,class jtermios.windows.JTermiosImpl$Port line 160, thread id 17, Thread-6, > CreateEventA(null, false, false, null)
log: 750726,class jtermios.windows.JTermiosImpl$Port line 160, thread id 17, Thread-6, < CreateEventA(null, false, false, null) => native@0x484
log: 750726,class jtermios.windows.JTermiosImpl$Port line 164, thread id 17, Thread-6, > CreateEventA(null, true, false, null)
log: 750726,class jtermios.windows.JTermiosImpl$Port line 164, thread id 17, Thread-6, < CreateEventA(null, true, false, null) => native@0x488
log: 750726,class jtermios.windows.JTermiosImpl$Port line 169, thread id 17, Thread-6, > CreateEventA(null, true, false, null)
log: 750727,class jtermios.windows.JTermiosImpl$Port line 169, thread id 17, Thread-6, < CreateEventA(null, true, false, null) => native@0x490
log: 750727,class jtermios.windows.JTermiosImpl$Port line 174, thread id 17, Thread-6, > CreateEventA(null, true, false, null)
log: 750727,class jtermios.windows.JTermiosImpl$Port line 174, thread id 17, Thread-6, < CreateEventA(null, true, false, null) => native@0x494
log: 750728,class jtermios.windows.JTermiosImpl$Port line 178, thread id 17, Thread-6, > CreateEventA(null, true, false, null)
log: 750728,class jtermios.windows.JTermiosImpl$Port line 178, thread id 17, Thread-6, < CreateEventA(null, true, false, null) => native@0x498
log: 750728,class jtermios.windows.JTermiosImpl$Port line 182, thread id 17, Thread-6, > CreateEventA(null, true, false, null)
log: 750728,class jtermios.windows.JTermiosImpl$Port line 182, thread id 17, Thread-6, < CreateEventA(null, true, false, null) => native@0x49c
log: 750728,class purejavacomm.PureJavaSerialPort line 1087, thread id 17, Thread-6, < open('COM82',00020006) => 0
log: 750729,class purejavacomm.PureJavaSerialPort line 1097, thread id 17, Thread-6, > fcntl(0, 3, 0)
log: 750729,class purejavacomm.PureJavaSerialPort line 1097, thread id 17, Thread-6, < fcntl(0, 3, 0) => 131078
log: 750729,class purejavacomm.PureJavaSerialPort line 1099, thread id 17, Thread-6, > fcntl(0, 4, 131074)
log: 750729,class purejavacomm.PureJavaSerialPort line 1099, thread id 17, Thread-6, < fcntl(0, 4, 131074) => 0
log: 750730,class purejavacomm.PureJavaSerialPort line 1107, thread id 17, Thread-6, > tcgetattr(0,jtermios.Termios@a1323da0)
log: 750730,class purejavacomm.PureJavaSerialPort line 1107, thread id 17, Thread-6, < tcgetattr(0,jtermios.Termios@d0c82aa0) => 0
log: 750730,class purejavacomm.PureJavaSerialPort line 1109, thread id 17, Thread-6, > cfmakeraw(0,jtermios.Termios@d0c82aa0)
log: 750730,class purejavacomm.PureJavaSerialPort line 1109, thread id 17, Thread-6, < cfmakeraw(0,jtermios.Termios@d0c82aa0)
log: 750730,class purejavacomm.PureJavaSerialPort line 1119, thread id 17, Thread-6, > tcsetattr(0,0,jtermios.Termios@975081c2)
log: 750731,class jtermios.windows.JTermiosImpl line 623, thread id 17, Thread-6, > GetCommState(native@0x480, [BaudRate 9600 fFlags 0001 wReserved 0 XonLim 2048 XoffLim 512 ByteSize 8 Parity 0 StopBits 0 XonChar 00 XoffChar 00 ErrorChar 00 EofChar 00 EvtChar 0A wReserved1 0])
log: 750731,class jtermios.windows.JTermiosImpl line 623, thread id 17, Thread-6, < GetCommState(native@0x480, [BaudRate 9600 fFlags 0001 wReserved 0 XonLim 2048 XoffLim 512 ByteSize 8 Parity 0 StopBits 0 XonChar 00 XoffChar 00 ErrorChar 00 EofChar 00 EvtChar 0A wReserved1 0]) => true
log: 750732,class jtermios.windows.JTermiosImpl line 701, thread id 17, Thread-6, > SetCommState(native@0x480, [BaudRate 9600 fFlags 0001 wReserved 0 XonLim 2048 XoffLim 512 ByteSize 8 Parity 0 StopBits 0 XonChar 11 XoffChar 13 ErrorChar 00 EofChar 00 EvtChar 0A wReserved1 0])
log: 750746,class jtermios.windows.JTermiosImpl line 701, thread id 17, Thread-6, < SetCommState(native@0x480, [BaudRate 9600 fFlags 0001 wReserved 0 XonLim 2048 XoffLim 512 ByteSize 8 Parity 0 StopBits 0 XonChar 11 XoffChar 13 ErrorChar 00 EofChar 00 EvtChar 0A wReserved1 0]) => true
log: 750746,class purejavacomm.PureJavaSerialPort line 1119, thread id 17, Thread-6, < tcsetattr(0,0,jtermios.Termios@975081c2) => 0
log: 750747,class purejavacomm.PureJavaSerialPort line 436, thread id 17, Thread-6, > setspeed(0,jtermios.Termios@975081c2,9600)
log: 750747,class purejavacomm.PureJavaSerialPort line 436, thread id 17, Thread-6, < setspeed(0,jtermios.Termios@975081c2,9600) => 0
log: 750747,class purejavacomm.PureJavaSerialPort line 518, thread id 17, Thread-6, > tcsetattr(0,0,jtermios.Termios@975081c2)
log: 750747,class purejavacomm.PureJavaSerialPort line 518, thread id 17, Thread-6, < tcsetattr(0,0,jtermios.Termios@975081c2) => 0
log: 750747,class purejavacomm.PureJavaSerialPort line 420, thread id 17, Thread-6, > tcsetattr(0,0,jtermios.Termios@975081c2)
log: 750748,class purejavacomm.PureJavaSerialPort line 420, thread id 17, Thread-6, < tcsetattr(0,0,jtermios.Termios@975081c2) => 0
log: 750748,class purejavacomm.PureJavaSerialPort line 1135, thread id 17, Thread-6, > ioctl(0,1074033770,[00000000])
log: 750748,class jtermios.windows.JTermiosImpl line 1044, thread id 17, Thread-6, > GetCommModemStatus(native@0x480,0x00000000)
log: 750748,class jtermios.windows.JTermiosImpl line 1044, thread id 17, Thread-6, < GetCommModemStatus(native@0x480,0x00000000) => true
log: 750748,class purejavacomm.PureJavaSerialPort line 1135, thread id 17, Thread-6, < ioctl(0,1074033770,[00000000]) => 0
log: 750749,class purejavacomm.PureJavaSerialPort line 1144, thread id 17, Thread-6, > pipe([2,0,0])
log: 750749,class purejavacomm.PureJavaSerialPort line 1144, thread id 17, Thread-6, < pipe([2,0,0]) => -1
log: 750752,class purejavacomm.PureJavaSerialPort line 420, thread id 17, Thread-6, > tcsetattr(0,0,jtermios.Termios@212d81c2)
log: 750752,class jtermios.windows.JTermiosImpl line 623, thread id 17, Thread-6, > GetCommState(native@0x480, [BaudRate 9600 fFlags 0001 wReserved 0 XonLim 2048 XoffLim 512 ByteSize 8 Parity 0 StopBits 0 XonChar 11 XoffChar 13 ErrorChar 00 EofChar 00 EvtChar 0A wReserved1 0])
log: 750753,class purejavacomm.PureJavaSerialPort$3 line 1226, thread id 18, COM82, > select(1,[0],[],[],jtermios.TimeVal@1249b99)
log: 750753,class jtermios.windows.JTermiosImpl line 623, thread id 17, Thread-6, < GetCommState(native@0x480, [BaudRate 9600 fFlags 0001 wReserved 0 XonLim 2048 XoffLim 512 ByteSize 8 Parity 0 StopBits 0 XonChar 11 XoffChar 13 ErrorChar 00 EofChar 00 EvtChar 0A wReserved1 0]) => true
log: 750754,class jtermios.windows.JTermiosImpl line 701, thread id 17, Thread-6, > SetCommState(native@0x480, [BaudRate 9600 fFlags 0001 wReserved 0 XonLim 2048 XoffLim 512 ByteSize 8 Parity 0 StopBits 0 XonChar 11 XoffChar 13 ErrorChar 00 EofChar 00 EvtChar 0A wReserved1 0])
log: 750754,class jtermios.windows.JTermiosImpl line 773, thread id 18, COM82, > ClearCommError(native@0x480, [0], [fFlags 0000 cbInQue 0 cbInQue 0])
log: 750754,class jtermios.windows.JTermiosImpl line 773, thread id 18, COM82, < ClearCommError(native@0x480, [0], [fFlags 0000 cbInQue 0 cbInQue 0]) => true
log: 750755,class jtermios.windows.JTermiosImpl line 821, thread id 18, COM82, > ResetEvent(native@0x49c)
log: 750755,class jtermios.windows.JTermiosImpl line 821, thread id 18, COM82, < ResetEvent(native@0x49c) => true
log: 750755,class jtermios.windows.JTermiosImpl line 830, thread id 18, COM82, > SetCommMask(native@0x480, 0x00000001)
log: 750760,class jtermios.windows.JTermiosImpl line 830, thread id 18, COM82, < SetCommMask(native@0x480, 0x00000001) => true
log: 750760,class jtermios.windows.JTermiosImpl line 833, thread id 18, COM82, > WaitCommEvent(native@0x480, [0], allocated@0x15b1f3b8 (20 bytes))
log: 750760,class jtermios.windows.JTermiosImpl line 833, thread id 18, COM82, < WaitCommEvent(native@0x480, [0], allocated@0x15b1f3b8 (20 bytes)) => false
log: 750760,class jtermios.windows.JTermiosImpl line 841, thread id 18, COM82, > GetLastError()
log: 750761,class jtermios.windows.JTermiosImpl line 841, thread id 18, COM82, < GetLastError() => 0
log: 750761,class jtermios.windows.JTermiosImpl$Port line 92, thread id 18, COM82, > GetLastError()
log: 750761,class jtermios.windows.JTermiosImpl$Port line 92, thread id 18, COM82, < GetLastError() => 0
log: 750761,class jtermios.windows.JTermiosImpl$Port line 94, thread id 18, COM82, > FormatMessageW(00001200,     null, 0, 1024, allocated@0x15b22ab0 (2048 bytes), 2048, null)
log: 750762,class jtermios.windows.JTermiosImpl$Port line 94, thread id 18, COM82, < FormatMessageW(00001200,     null, 0, 1024, allocated@0x15b22ab0 (2048 bytes), 2048, null) => 41
log: 750762,class jtermios.windows.JTermiosImpl line 842, thread id 18, COM82, fail() class jtermios.windows.JTermiosImpl line 842, Windows GetLastError()= 0, La operación se completó correctamente.

jtermios.windows.JTermiosImpl$Fail
    at jtermios.windows.JTermiosImpl$Port.fail(JTermiosImpl.java:100)
    at jtermios.windows.JTermiosImpl.select(JTermiosImpl.java:842)
    at jtermios.JTermios.select(JTermios.java:439)
    at purejavacomm.PureJavaSerialPort$3.run(PureJavaSerialPort.java:1226)
    at java.lang.Thread.run(Thread.java:745)
log: 750763,class purejavacomm.PureJavaSerialPort$3 line 1226, thread id 18, COM82, < select(1,[],[],[],jtermios.TimeVal@1249b99) => -1
log: 750763,class purejavacomm.PureJavaSerialPort$3 line 1234, thread id 18, COM82, > errno()
log: 750763,class purejavacomm.PureJavaSerialPort$3 line 1234, thread id 18, COM82, < errno() => 24
log: 750763,class java.lang.Thread line 745, thread id 18, COM82, select() or poll() returned -1, errno 24
log: 750772,class jtermios.windows.JTermiosImpl line 701, thread id 17, Thread-6, < SetCommState(native@0x480, [BaudRate 9600 fFlags 0001 wReserved 0 XonLim 2048 XoffLim 512 ByteSize 8 Parity 0 StopBits 0 XonChar 11 XoffChar 13 ErrorChar 00 EofChar 00 EvtChar 0A wReserved1 0]) => true
log: 750772,class purejavacomm.PureJavaSerialPort line 420, thread id 17, Thread-6, < tcsetattr(0,0,jtermios.Termios@212d81c2) => 0
log: 750773,class purejavacomm.PureJavaSerialPort line 1027, thread id 18, COM82, > fcntl(0, 3, 0)
log: 750773,class purejavacomm.PureJavaSerialPort line 1027, thread id 18, COM82, < fcntl(0, 3, 0) => 131074
log: 750773,class purejavacomm.PureJavaSerialPort line 1029, thread id 18, COM82, > fcntl(0, 4, 131078)
log: 750773,class purejavacomm.PureJavaSerialPort line 1029, thread id 18, COM82, < fcntl(0, 4, 131078) => 0
log: 750773,class purejavacomm.PureJavaSerialPort line 1035, thread id 18, COM82, > close(0)
log: 750774,class jtermios.windows.JTermiosImpl$Port line 205, thread id 18, COM82, > SetEvent(native@0x488)
log: 750774,class jtermios.windows.JTermiosImpl$Port line 205, thread id 18, COM82, < SetEvent(native@0x488) => true
log: 750774,class jtermios.windows.JTermiosImpl$Port line 210, thread id 18, COM82, > CloseHandle(native@0x494)
log: 750774,class jtermios.windows.JTermiosImpl$Port line 210, thread id 18, COM82, < CloseHandle(native@0x494) => true
log: 750774,class jtermios.windows.JTermiosImpl$Port line 213, thread id 18, COM82, > CloseHandle(native@0x488)
log: 750774,class jtermios.windows.JTermiosImpl$Port line 213, thread id 18, COM82, < CloseHandle(native@0x488) => true
log: 750775,class jtermios.windows.JTermiosImpl$Port line 218, thread id 18, COM82, > SetEvent(native@0x490)
log: 750775,class jtermios.windows.JTermiosImpl$Port line 218, thread id 18, COM82, < SetEvent(native@0x490) => true
log: 750775,class jtermios.windows.JTermiosImpl$Port line 224, thread id 18, COM82, > CloseHandle(native@0x498)
log: 750775,class jtermios.windows.JTermiosImpl$Port line 224, thread id 18, COM82, < CloseHandle(native@0x498) => true
log: 750775,class jtermios.windows.JTermiosImpl$Port line 227, thread id 18, COM82, > CloseHandle(native@0x490)
log: 750775,class jtermios.windows.JTermiosImpl$Port line 227, thread id 18, COM82, < CloseHandle(native@0x490) => true
log: 750775,class jtermios.windows.JTermiosImpl$Port line 232, thread id 18, COM82, > SetEvent(native@0x484)
log: 750776,class jtermios.windows.JTermiosImpl$Port line 232, thread id 18, COM82, < SetEvent(native@0x484) => true
log: 750776,class jtermios.windows.JTermiosImpl$Port line 235, thread id 18, COM82, > CloseHandle(native@0x484)
log: 750776,class jtermios.windows.JTermiosImpl$Port line 235, thread id 18, COM82, < CloseHandle(native@0x484) => true
log: 750776,class jtermios.windows.JTermiosImpl$Port line 241, thread id 18, COM82, > CloseHandle(native@0x49c)
log: 750776,class jtermios.windows.JTermiosImpl$Port line 241, thread id 18, COM82, < CloseHandle(native@0x49c) => true
log: 750776,class jtermios.windows.JTermiosImpl$Port line 244, thread id 18, COM82, > CloseHandle(native@0x480)
log: 750888,class jtermios.windows.JTermiosImpl$Port line 244, thread id 18, COM82, < CloseHandle(native@0x480) => true
log: 750888,class purejavacomm.PureJavaSerialPort line 1035, thread id 18, COM82, < close(0) => 0
nyholku commented 9 years ago

@PeteSL Wild guess: could it be that GetLastError no longer functions and always returns 0?

PeteSL commented 9 years ago

@nyholku No, it is working correctly. I will post a response because I "think" I know what is going on.

PeteSL commented 9 years ago

Thank you, this is -exactly- the same problem I was seeing earlier in some of my first tests! I am not sure why the translation was originally Exception in thread "Thread-8" purejavacomm.PureJavaIllegalStateException: File descriptor is -1 < 0, maybe closed by previous error condition but this error is actually zero (GetLastError() => 0) which is operation success! Ok, so what does that mean? Possibly that an event already triggered and is waiting in the integer passed to WaitCommEvent? (in this case, I believe the Overlapped structure would be ignored). I will research further...

nyholku commented 9 years ago

@PeteSL Could be timing, now that things are working faster you may have uncovered a bug in the original logic.

PeteSL commented 9 years ago

@nyholku When I currently run with logging on, GetLastError() is returning ERROR_IO_PENDING (in my case). I agree I think what we have going on is a timing issue so what is the solution? When I was seeing this "error", I tried moving your GetOverlappedResults code down to after a test for GetLastError() == 0 but that also failed. I am doing some quick research to see if this has shown up in the Windows world. I am guessing we might be able to take the results from the port.m_EventFlags without doing a GetOverlappedResults (maybe do the ready = maskToFDSets(port, readfds, writefds, exceptfds, ready); line only if GetLastError() == 0 ?

PeteSL commented 9 years ago

@nyholku I am looking further and found that GetLastError() is -really- timing sensitive in that -nothing- can come between the failing statement and GetLastError(). Hmm, I will look closely at what we can do about this. Maybe just get the error and, if it is zero or ERROR_IO_PENDING, let consider it ok.

PeteSL commented 9 years ago

@nyholku I am going to ask him to change the line to if (Native.GetLastError() == ERROR_IO_PENDING) and see if that fixes it. If it does, then what we have is a timing issue with the logging functions causing system calls and clearing the error.

PeteSL commented 9 years ago

I am going to ask you to turn of logging again (remove the -Dpurejavacomm.loglevel=9) and change line 842 to if (Native.GetLastError() != ERROR_IO_PENDING) (note the addition of the Native. prefix to GetLastError()) Please let us know what happens.

PeteSL commented 9 years ago

@nyholku my thinking is that Windows GetLastError() is -very- timing sensitive and if -any- kernel calls are done in between by the application (and Java does a lot of memory games), that this might report back incorrectly. If this works, then what we need to do is consider if GetLastError() == ERROR_IO_PENDING or 0 that any of the overlapped functions worked (WaitCommEvent, reads and writes).

malkavi commented 9 years ago

The class is "jtermios.windows.JTermiosImpl.java"?? line 841 "if (GetLastError() != ERROR_IO_PENDING)"? to "if (Native.getLastError() != ERROR_IO_PENDING)"?

PeteSL commented 9 years ago

Yes. sorry about that.

PeteSL commented 9 years ago

And you got the case correct on Native.getLastError()

PeteSL commented 9 years ago

What we are thinking is something in the Java application is making a Windows call between the WaitCommEvent and the GetLastError call. We know, for a fact, that log is called in WinAPI and that may be causing memory allocations/changes/etc. Anyway, if this works, that points to something that was there all of the time, just not as common. If this works, we will probably have to look at altering the code in all places where it checks for GetLastError() == ERROR_IO_PENDING to also consider 0 as being the same. This is just a guess on my part until we can do some more testing. Your results will be very helpful.

malkavi commented 9 years ago

The error still continues

jtermios.windows.JTermiosImpl$Fail
    at jtermios.windows.JTermiosImpl$Port.fail(JTermiosImpl.java:100)
    at jtermios.windows.JTermiosImpl.select(JTermiosImpl.java:842)
    at jtermios.JTermios.select(JTermios.java:439)
    at purejavacomm.PureJavaSerialPort$3.run(PureJavaSerialPort.java:1226)
    at java.lang.Thread.run(Thread.java:745)
malkavi commented 9 years ago

Wait, now is working. :| I will do more test to be sure.

PeteSL commented 9 years ago

Ah, then I think we have identified our issue. Ok, then this is next. At line 841, change the line to be the following: int err = Native.getLastError(); if (err != ERROR_IO_PENDING && err != 0) What I am doing is seeing if the code executes fine if we allow Java to make system calls in between the WaitCommEvent call and the GetLastError call since we can't ensure atomic operation. If that works, we will need to look at making the same change at line 452 and 513.

PeteSL commented 9 years ago

By the way, thank you very much for reporting this bug. This is a tough one to isolate and I appreciate you working with me on this.

malkavi commented 9 years ago

Wait... I have see that somehow jna-4.0.0.jar wasn't in my path. I have reverted all changes to test from scratch, and It's working, but after obfuscate the code the issues is there. Now I will try with the change.

PeteSL commented 9 years ago

I am testing with jna-4.1.0.jar so you might want to download to the latest. In any case, I think you have identified a timing issue which would always be present and would vary as to when it would show up. I am currently working on updated code that will remove the WinAPI GetLastError and replace it with Native.getLastError(). I will also allow both ERROR_IO_PENDING and 0 for the 3 overlapped calls just in case Java gets ambitious in between calls.

PeteSL commented 9 years ago

My initial testing shows at least I didn't break anything by making those changes. :-) Very interested in your results.

malkavi commented 9 years ago

I have tried compiling but with -dontobfuscate, same result/error. Launching from eclipse works, but from the jar doesn't. Also tried without any obfuscate without success. At least is not related to obfuscation.

PeteSL commented 9 years ago

Did you try with the suggestion of changing lines 841, 452 and 531 to: int err = Native.getLastError(); if (err != ERROR_IO_PENDING && err != 0)

PeteSL commented 9 years ago

This is important because it appears Java is doing something in between the WaitCommEvent and GetLastError calls. At least this allows us to assume that if GetLastError() == 0, then Java did something and we should go on.

malkavi commented 9 years ago

It's working! I have tried also obfuscating the code and works! I have changed the lines 841,513 and 452. Thanks! There are more GetLastError, are you going to change those also?

PeteSL commented 9 years ago

Yes, the code I am sending on for approval replaces all GetLastError() calls with Native.getLastError() in the Windows implementation but the only "safe to assume zero is ok" places are after overlapped operations like those 3 places.

PeteSL commented 9 years ago

@nyholku Source is coming to you in an email soon.

nyholku commented 9 years ago

On 2 Sep 2015, at 18:34, PeteSL notifications@github.com wrote:

@nyholku Source is coming to you in an email soon.

— Reply to this email directly or view it on GitHub.

Thanks, just got home and read through your excange in github.

Nice debugging.

Still I'm wondering if the root cause is that something makes a system call that clears the error between waitevent and getlasterror. Granted, if logging is on, this is even likely to happen but otherwise how/why? AFAIU the last error is thread specific so no other part of the code should be able to do it and if the JVM were to do it at any time this would make getlasterror more or less useless and a google search should find other people having this same issue.

What do you think?

br Kusti

PeteSL commented 9 years ago

@nyholku this may have to do with how direct mapping may be handling memory management with structures but that is just a guess.

Sent from my Windows Phone

From: nyholkumailto:notifications@github.com Sent: ‎9/‎2/‎2015 11:57 AM To: nyholku/purejavacommmailto:purejavacomm@noreply.github.com Cc: Peter Loveallmailto:psl@ametx.com Subject: Re: [purejavacomm] jtermios.windows.JTermiosImpl$Fail after update from v0.0.22 to v0.0.24 (#57)

On 2 Sep 2015, at 18:34, PeteSL notifications@github.com wrote:

@nyholku Source is coming to you in an email soon.

— Reply to this email directly or view it on GitHub.

Thanks, just got home and read through your excange in github.

Nice debugging.

Still I'm wondering if the root cause is that something makes a system call that clears the error between waitevent and getlasterror. Granted, if logging is on, this is even likely to happen but otherwise how/why? AFAIU the last error is thread specific so no other part of the code should be able to do it and if the JVM were to do it at any time this would make getlasterror more or less useless and a google search should find other people having this same issue.

What do you think?

br Kusti

— Reply to this email directly or view it on GitHubhttps://github.com/nyholku/purejavacomm/issues/57#issuecomment-137170241.

nyholku commented 9 years ago

Yes,

I will incorporate your changes as they seem to help but I will also aske guidance in the JNA list, the real experts there may be able cast some light into this.

br Kusti

On 2 Sep 2015, at 20:21, PeteSL notifications@github.com wrote:

@nyholku this may have to do with how direct mapping may be handling memory management with structures but that is just a guess.

Sent from my Windows Phone

From: nyholkumailto:notifications@github.com Sent: ‎9/‎2/‎2015 11:57 AM To: nyholku/purejavacommmailto:purejavacomm@noreply.github.com Cc: Peter Loveallmailto:psl@ametx.com Subject: Re: [purejavacomm] jtermios.windows.JTermiosImpl$Fail after update from v0.0.22 to v0.0.24 (#57)

On 2 Sep 2015, at 18:34, PeteSL notifications@github.com wrote:

@nyholku Source is coming to you in an email soon.

— Reply to this email directly or view it on GitHub.

Thanks, just got home and read through your excange in github.

Nice debugging.

Still I'm wondering if the root cause is that something makes a system call that clears the error between waitevent and getlasterror. Granted, if logging is on, this is even likely to happen but otherwise how/why? AFAIU the last error is thread specific so no other part of the code should be able to do it and if the JVM were to do it at any time this would make getlasterror more or less useless and a google search should find other people having this same issue.

What do you think?

br Kusti

— Reply to this email directly or view it on GitHubhttps://github.com/nyholku/purejavacomm/issues/57#issuecomment-137170241. — Reply to this email directly or view it on GitHub.

PeteSL commented 9 years ago

I think I found it... The comment about last error in their FAQs is: Obtaining "last" error If a function sets the system error property (errno or GetLastError()), the error code will be thrown as a LastErrorException if you declare the exception in your JNA mapping. Alternatively, you can use Native.getLastError() to retrieve it, providing that Native.setPreserveLastError(boolean) has been called with a true value. Throwing an exception is preferred since it has better performance. - See more at: https://jna.java.net/javadoc/overview-summary.html#last-error So we can do that (add throws LastErrorException to the native declarations or, for simplicity sake, add Native.setPreserveLastError(true) to the static initializer for each of the implementations. And this is why that needs to be done (from setPreserveLastError JavaDoc): setPreserveLastError public static void setPreserveLastError(boolean enable) Deprecated. The preferred method of obtaining the last error result is to declare your mapped method to throw LastErrorException instead.

Set whether the system last error result is captured after every native invocation. Defaults to true (false for direct-mapped calls).- See more at: https://jna.java.net/javadoc/com/sun/jna/Native.html#setPreserveLastError(boolean)

So, this is why this became an issue with Direct Mapping that wasn't there in JNA mode (note the defaults for setPreserveLastError()).

So, I would say, for testing purposes, add Native.setPreserveLastError(true) to the last line of the static initializer (no indicator of whether this should be done first or after the library is loaded) and change back the code to its original. If everything works, we know that was the problem...

PeteSL commented 9 years ago

In looking at 4.1, it says for setPreserveLastError(): Deprecated. Last error is always preserved

This method is obsolete. The last error value is always preserved. NOTE: The preferred method of obtaining the last error result is to declare your mapped method to throw LastErrorException.

In fact, in 4.1 code it does nothing. so we are back to implementing LastErrorException I guess because it is obvious that without setPreserveLastError, direct mapping actually does not preserver last error :-(

PeteSL commented 9 years ago

I am currently looking to determine what triggers JNA to check GetLastError for LastErrorException. I am guessing possibly whether the function returns false or not but I will check...

PeteSL commented 9 years ago

They say they always preserve GetLastError but, obviously, that isn't true. I couldn't ascertain in my short look through the JNA c code what actually triggers throwing that exception. I would hate to depend on their implementation of LastErrorException to only be thrown if there is an error. I have a funny feeling, after what we saw, that 4.1 is still not preserving the last error for direct mapping, contrary to their statement in JavaDoc and their Java implementation. For the moment, lets go with this. We can revisit later to see about throwing LastErrorException on all calls that might throw an error. We would need a lot of testing there.

roniegh commented 9 years ago

Isn't it a reincarnation of the error fixed by nyholku/purejavacomm#17 ?

PeteSL commented 9 years ago

Not from what I can see. That was a case where WaitCommEvent was being called before the prior WaitCommEvent (or other overlapped action that was using the same event handle) was completed. This is an issue with GetLastError being checked and stored immediately after every function call (yes, I have ascertained this in dispatch.c) but then that value is being overwritten before we are able to check it. Also, I have ascertained that LastErrorException is thrown any time GetLastError (or errno) is non-zero and you have defined throws LastErrorException for the function. This is true across the board. I am going to review the code to see what can be done to implement this exception but, for the moment, the current changes are working.

PeteSL commented 9 years ago

Does 0.25 fix this issue so we can close it?

malkavi commented 9 years ago

Sorry, i forgot to close the issue. I tried 0.0.25 and it works. Thanks.