ComportIdentifier.open is indefinitely blocking

[vicentini]

I have an application where I periodically read data from a serial port. Because the port name could change at any time, I always open the necessary port, request and read data and close the port afterwards. After some time, the port cannot be opened any longer. As you can see in the attached log (log level 5) the native call inside "PureJavaSerialPort-constructor" => "JTermios.open" is not returning anymore and blocking forever. (The first open/close call you see in line 1-6 happens in the CommPortIdentifier.getPortIdentifier method and is still working. The subsequent call to the same underlying open method not anymore.) AFAIK this shouldn't happen, because the passed attribute O_NONBLOCK should prevent the method from blocking.

Has anyone experienced anything similar? Is this a known issue?

Log output of a correctly working read process:

log: > open('/dev/ttyUSB0',00000902) log: < open('/dev/ttyUSB0',00000902) => 111 log: > tcgetattr(111,jtermios.Termios@a1323da0) log: < tcgetattr(111,jtermios.Termios@2a24aa94) => 0 log: > close(111) log: < close(111) => 0 log: > open('/dev/ttyUSB0',00000902) log: < open('/dev/ttyUSB0',00000902) => 111 log: > fcntl(111, 3, 0) log: < fcntl(111, 3, 0) => 2050 log: > fcntl(111, 4, 2) log: < fcntl(111, 4, 2) => 0 log: > tcgetattr(111,jtermios.Termios@a1323da0) log: < tcgetattr(111,jtermios.Termios@2a24aa94) => 0 log: > cfmakeraw(111,jtermios.Termios@2a24aa94) log: < cfmakeraw(111,jtermios.Termios@406cf16d) log: > tcsetattr(111,0,jtermios.Termios@58cb1b0e) log: < tcsetattr(111,0,jtermios.Termios@58cb1b0e) => 0 log: > setspeed(111,jtermios.Termios@58cb1b0e,9600) log: > ioctl(111,21534,JTermiosImpl$serial_struct(auto-allocated@0x919f3570 (60 bytes)) { int type@0=0 int line@4=0 int port@8=0 int irq@c=0 int flags@10=0 int xmit_fifo_size@14=0 int custom_divisor@18=0 int baud_base@1c=0 short close_delay@20=0 short io_type@22=0 int hub6@24=0 short closing_wait@28=0 short closing_wait2@2a=0 Pointer iomem_base@2c=null short iomem_reg_shift@30=0 int port_high@34=0 NativeLong iomap_base@38=0 }) log: < tcsetattr(111,21534,JTermiosImpl$serial_struct(auto-allocated@0x919f3570 (60 bytes)) { int type@0=0 int line@4=0 int port@8=0 int irq@c=0 int flags@10=0 int xmit_fifo_size@14=0 int custom_divisor@18=0 int baud_base@1c=0 short close_delay@20=0 short io_type@22=0 int hub6@24=0 short closing_wait@28=0 short closing_wait2@2a=0 Pointer iomem_base@2c=null short iomem_reg_shift@30=0 int port_high@34=0 NativeLong iomap_base@38=0 }) => 0 log: > ioctl(111,21535,JTermiosImpl$serial_struct(auto-allocated@0x919f3570 (60 bytes)) { int type@0=0 int line@4=0 int port@8=0 int irq@c=0 int flags@10=0 int xmit_fifo_size@14=0 int custom_divisor@18=0 int baud_base@1c=0 short close_delay@20=0 short io_type@22=0 int hub6@24=0 short closing_wait@28=0 short closing_wait2@2a=0 Pointer iomem_base@2c=null short iomem_reg_shift@30=0 int port_high@34=0 NativeLong iomap_base@38=0 }) log: < tcsetattr(111,21535,JTermiosImpl$serial_struct(auto-allocated@0x919f3570 (60 bytes)) { int type@0=0 int line@4=0 int port@8=0 int irq@c=0 int flags@10=0 int xmit_fifo_size@14=0 int custom_divisor@18=0 int baud_base@1c=0 short close_delay@20=0 short io_type@22=0 int hub6@24=0 short closing_wait@28=0 short closing_wait2@2a=0 Pointer iomem_base@2c=null short iomem_reg_shift@30=0 int port_high@34=0 NativeLong iomap_base@38=0 }) => 0 log: > cfgetospeed(jtermios.Termios@58cb1b0e,13) log: < cfgetospeed(jtermios.Termios@58cb1b0e,13) => 0 log: > cfgetospeed(jtermios.Termios@58cb1b0e,13) log: < cfgetospeed(jtermios.Termios@58cb1b0e,13) => 0 log: > tcsetattr(111,0,jtermios.Termios@58cb1b0e) log: < tcsetattr(111,0,jtermios.Termios@58cb1b0e) => 0 log: < setspeed(111,jtermios.Termios@58cb1b0e,9600) => 0 log: > tcsetattr(111,0,jtermios.Termios@58cb1b0e) log: < tcsetattr(111,0,jtermios.Termios@58cb1b0e) => 0 log: > tcsetattr(111,0,jtermios.Termios@58cb1b0e) log: < tcsetattr(111,0,jtermios.Termios@58cb1b0e) => 0 log: > ioctl(111,21525,[[0]]) log: < ioctl(111,21525,[[38]]) => 0 log: > pipe([2,0,0]) log: < pipe([2,123,124]) => 0 log: > fcntl(123, 3, 0) log: < fcntl(123, 3, 0) => 0 log: > fcntl(123, 4, 2048) log: < fcntl(123, 4, 2048) => 0 log: > setspeed(111,jtermios.Termios@58cb1b0e,9600) log: > ioctl(111,21534,JTermiosImpl$serial_struct(auto-allocated@0x92c64fe0 (60 bytes)) { int type@0=0 int line@4=0 int port@8=0 int irq@c=0 int flags@10=0 int xmit_fifo_size@14=0 int custom_divisor@18=0 int baud_base@1c=0 short close_delay@20=0 short io_type@22=0 int hub6@24=0 short closing_wait@28=0 short closing_wait2@2a=0 Pointer iomem_base@2c=null short iomem_reg_shift@30=0 int port_high@34=0 NativeLong iomap_base@38=0 }) log: < tcsetattr(111,21534,JTermiosImpl$serial_struct(auto-allocated@0x92c64fe0 (60 bytes)) { int type@0=0 int line@4=0 int port@8=0 int irq@c=0 int flags@10=0 int xmit_fifo_size@14=0 int custom_divisor@18=0 int baud_base@1c=0 short close_delay@20=0 short io_type@22=0 int hub6@24=0 short closing_wait@28=0 short closing_wait2@2a=0 Pointer iomem_base@2c=null short iomem_reg_shift@30=0 int port_high@34=0 NativeLong iomap_base@38=0 }) => 0 log: > ioctl(111,21535,JTermiosImpl$serial_struct(auto-allocated@0x92c64fe0 (60 bytes)) { int type@0=0 int line@4=0 int port@8=0 int irq@c=0 int flags@10=0 int xmit_fifo_size@14=0 int custom_divisor@18=0 int baud_base@1c=0 short close_delay@20=0 short io_type@22=0 int hub6@24=0 short closing_wait@28=0 short closing_wait2@2a=0 Pointer iomem_base@2c=null short iomem_reg_shift@30=0 int port_high@34=0 NativeLong iomap_base@38=0 }) log: < tcsetattr(111,21535,JTermiosImpl$serial_struct(auto-allocated@0x92c64fe0 (60 bytes)) { int type@0=0 int line@4=0 int port@8=0 int irq@c=0 int flags@10=0 int xmit_fifo_size@14=0 int custom_divisor@18=0 int baud_base@1c=0 short close_delay@20=0 short io_type@22=0 int hub6@24=0 short closing_wait@28=0 short closing_wait2@2a=0 Pointer iomem_base@2c=null short iomem_reg_shift@30=0 int port_high@34=0 NativeLong iomap_base@38=0 }) => 0 log: > cfgetospeed(jtermios.Termios@58cb1b0e,13) log: < cfgetospeed(jtermios.Termios@58cb1b0e,13) => 0 log: > cfgetospeed(jtermios.Termios@58cb1b0e,13) log: < cfgetospeed(jtermios.Termios@58cb1b0e,13) => 0 log: > tcsetattr(111,0,jtermios.Termios@58cb1b0e) log: < tcsetattr(111,0,jtermios.Termios@58cb1b0e) => 0 log: < setspeed(111,jtermios.Termios@58cb1b0e,9600) => 0 log: > tcsetattr(111,0,jtermios.Termios@da3ba0e) log: < tcsetattr(111,0,jtermios.Termios@da3ba0e) => 0 log: > tcsetattr(111,0,jtermios.Termios@da3ba0e) log: < tcsetattr(111,0,jtermios.Termios@da3ba0e) => 0 log: > ioctl(111,21531,[[0]]) log: < ioctl(111,21531,[[0]]) => 0 log: > poll([2,jtermios.Pollfd@1d5c312,jtermios.Pollfd@1123a58],2,-1) log: > write(111,[256,0x02,0x04,0x00,0x00,0x00,0x01,0x31,0xF9...],8) log: < write(111,[256,0x02,0x04,0x00,0x00,0x00,0x01,0x31,0xF9...],8) => 8 log: > tcdrain(111) log: < tcdrain(111) => 0 log: > tcsetattr(111,0,jtermios.Termios@733f2777) log: < tcsetattr(111,0,jtermios.Termios@733f2777) => 0 log: > poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) log: < poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) => 1 log: > read(111,[1,0x00],1) log: < read(111,[1,0x02],1) => 1 log: > poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) log: < poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) => 1 log: > read(111,[1,0x00],1) log: < read(111,[1,0x04],1) => 1 log: > poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) log: < poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) => 1 log: > read(111,[1,0x00],1) log: < read(111,[1,0x02],1) => 1 log: > tcsetattr(111,0,jtermios.Termios@2a24aa94) log: < tcsetattr(111,0,jtermios.Termios@2a24aa94) => 0 log: > poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) log: < poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) => 1 log: > read(111,[256,0x00,0x00,0x00,0x00,0x00,0x00,0x00,0x00...],4) log: < read(111,[256,0x00,0x64,0xFC,0xDB,0x00,0x00,0x00,0x00...],4) => 4 log: > ioctl(111,21531,[[0]]) log: < ioctl(111,21531,[[0]]) => 0 log: > write(111,[256,0x02,0x04,0x00,0x01,0x00,0x01,0x60,0x39...],8) log: < write(111,[256,0x02,0x04,0x00,0x01,0x00,0x01,0x60,0x39...],8) => 8 log: > tcdrain(111) log: < tcdrain(111) => 0 log: > tcsetattr(111,0,jtermios.Termios@733f2777) log: < tcsetattr(111,0,jtermios.Termios@733f2777) => 0 log: > poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) log: < poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) => 1 log: > read(111,[1,0x00],1) log: < read(111,[1,0x02],1) => 1 log: > poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) log: < poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) => 1 log: > read(111,[1,0x00],1) log: < read(111,[1,0x04],1) => 1 log: > poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) log: < poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) => 1 log: > read(111,[1,0x00],1) log: < read(111,[1,0x02],1) => 1 log: > tcsetattr(111,0,jtermios.Termios@2a24aa94) log: < tcsetattr(111,0,jtermios.Termios@2a24aa94) => 0 log: > poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) log: < poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) => 1 log: > read(111,[256,0x00,0x00,0x00,0x00,0x00,0x00,0x00,0x00...],4) log: < read(111,[256,0x00,0x1B,0xBD,0x3B,0x00,0x00,0x00,0x00...],4) => 4 log: > ioctl(111,21531,[[0]]) log: < ioctl(111,21531,[[0]]) => 0 log: > write(111,[256,0x02,0x03,0x00,0x0A,0x00,0x01,0xA4,0x3B...],8) log: < write(111,[256,0x02,0x03,0x00,0x0A,0x00,0x01,0xA4,0x3B...],8) => 8 log: > tcdrain(111) log: < tcdrain(111) => 0 log: > tcsetattr(111,0,jtermios.Termios@733f2777) log: < tcsetattr(111,0,jtermios.Termios@733f2777) => 0 log: > poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) log: < poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) => 1 log: > read(111,[1,0x00],1) log: < read(111,[1,0x02],1) => 1 log: > poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) log: < poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) => 1 log: > read(111,[1,0x00],1) log: < read(111,[1,0x03],1) => 1 log: > poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) log: < poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) => 1 log: > read(111,[1,0x00],1) log: < read(111,[1,0x02],1) => 1 log: > tcsetattr(111,0,jtermios.Termios@2a24aa94) log: < tcsetattr(111,0,jtermios.Termios@2a24aa94) => 0 log: > poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) log: < poll([2,jtermios.Pollfd@12c2855,jtermios.Pollfd@f7d269],2,1000) => 1 log: > read(111,[256,0x00,0x00,0x00,0x00,0x00,0x00,0x00,0x00...],4) log: < read(111,[256,0x00,0x00,0xFC,0x44,0x00,0x00,0x00,0x00...],4) => 4 log: > write(124,[1,0x00],1) log: < write(124,[1,0x00],1) => 1 log: < poll([2,jtermios.Pollfd@1d5c312,jtermios.Pollfd@1123a58],2,-1) => 1 log: > fcntl(111, 3, 0) log: > read(123,[1,0x00],1) log: < fcntl(111, 3, 0) => 2 log: > fcntl(111, 4, 2050) log: < read(123,[1,0x00],1) => 1 log: < fcntl(111, 4, 2050) => 0 log: > close(111) log: < close(111) => 0 log: > close(123) log: < close(123) => 0 log: > close(124) log: < close(124) => 0

Log output when the library is not able to connect:

log: > open('/dev/ttyUSB0',00000902) log: < open('/dev/ttyUSB0',00000902) => 111 log: > tcgetattr(111,jtermios.Termios@a1323da0) log: < tcgetattr(111,jtermios.Termios@2a24aa94) => 0 log: > close(111) log: < close(111) => 0 log: > open('/dev/ttyUSB0',00000902)

BTW, the application is running on linux with jdk1.8.0_91.

[cstheorist]

I have recently seen something similar. I have not collected as much data just yet but a jstack clearly shows that I have a thread blocked on the JNA call to clib.open.

[nyholku]

@vicentini

I suppose you have made sure that every time you open the port, it gets closed ok too, right thought so.

Approximately how many times you can open/close the port before the open hangs?

Can you simplify this to simple test case that just keeps opening and closing a port?

If so, could you run the test with some other serial device in case this is a driver bug?

[nyholku]

Closing this as there has been no response and I cannot reproduce this.