search

area515 / Photonic3D

Control software for resin 3D printers
http://photonic3d.com
GNU General Public License v3.0
133 stars 112 forks source link

Projector Serial Port Autodetect Corrupts Firmware Serial Connection #116

Closed jmkao closed 8 years ago

jmkao commented 8 years ago

When the projector serial port is set manually to /dev/ttyUSB1, projector detection and the firmware serial connection both work fine. Projector on/off works fine, and I can successfully control the motors, with the following pattern in the log.out:

echo:  M205 S0.000 T0.000 B20000 X20.000 Z0.400 E5.000
echo:Home offset (mm):
echo:  M206 X0.000 Y0.000 Z0.000
echo:PID settings:
echo:   M301 P22.200 I1.080 D114.000
ok

lineRead:ok

lineRead:ok

lineRead:ok

lineRead:ok

lineRead:ok

The lineRead:ok lines represent successful motor control button presses.

When the projector serial port is set to autodetect, the initial firmware connection appears to work fine from the log.out, but then the message Timeout after bytes read "" is output to log.out while projector autodetection is ongoing. Once the printer starts, projector on/off works fine, but the motor buttons show no response:

echo:  M205 S0.000 T0.000 B20000 X20.000 Z0.400 E5.000
echo:Home offset (mm):
echo:  M206 X0.000 Y0.000 Z0.000
echo:PID settings:
echo:   M301 P22.200 I1.080 D114.000
ok

Timeout after bytes read ""
Timeout after bytes read ""

If I stop the printer and return the projector settings to /dev/ttyUSB1, then everything works again.

LogBundle.zip is attached: LogBundle.zip

WesGilster commented 8 years ago

I can replicate the timeouts but these are generally going to be normal with autodetection because the firmware doesn't understand our printer hex codes and projectors don't understand gcode. What I haven't been able to replicate is the unresponsive buttons. I'll keep on trying to replicate this and verify that I'm right about the timeouts. Hopefully this is 100% reproducible for you right?

If I can't reproduce the issue, I'm probably going to make a massive change to move to log4j and end this sysout stuff. That way I'll get all of the information I need from your situation. It's a very easy change, but there are a ton of changes to make. It's also long over due, and we'll have some pretty impressive log options when I'm done.

WesGilster commented 8 years ago

I actually found the error in your error log. I could fix the NPEs that were in there, but I haven't been able to recreate or even determine the path that the application took that caused you to receive them. Before this point the logging has been pretty sad.

I've added further debugging statements and introduced log4j2(#65) to make sure I can correlate exceptions with execution times since that wasn't possible before.

I've also increased the logging level for the 3 classes that will contain your bug. These are in our default log4j configuration. I'll turn this all off to get our performance back when that future event comes.

Unfortunately, I have to ask that you replicate this again and send me the log bundle. Hopefully we can smash it this time...

jmkao commented 8 years ago

Ok, I replicated it and have attached the log bundle. I did the following sequence twice:

(1) Set firmware to /dev/ttyUSB2, set projector to autodetect (2) Start printer (3) Move the Z axis (4) Stop printer (5) set firmware to /dev/ttyUSB2, set projector to /dev/ttyUSB1 (6) Start printer (7) Move the Z axis (8) Stop printer

When the projector is set to autodetect, the log shows that G91 being sent by the Z axis move command, but a firmware response is not seen on the serial line even after 20 seconds, and an exception is thrown when the printer is stopped:

2016-01-26 05:09:55,393 INFO o.a.r.s.SerialManager [qtp12042244-16] Completed assignment of projector:Acer using serialP
ort:org.area515.resinprinter.serial.JSSCCommPort@140c3f with settings:{Port:/dev/ttyUSB1 speed:9600 databits:8 parity:None stopbits:One handshake:null} to printer:Titan 1(printerFirmwareSerialPort:org.area515.resinprinter.serial.JSSCCommPort@f14b92, projectorSerialPort:org.area515.resinprinter.serial.JSSCCommPort@140c3f Display::0.0)
2016-01-26 05:09:55,395 DEBUG o.a.r.p.PrinterManager [qtp12042244-16] Assigned projector:Autodetect projector to:Titan 1(printerFirmwareSerialPort:org.area515.resinprinter.serial.JSSCCommPort@f14b92, projectorSerialPort:org.area515.resinprinter.serial.JSSCCommPort@140c3f Display::0.0)
2016-01-26 05:09:55,397 INFO o.a.r.p.PrinterManager [qtp12042244-16] Printer started:Titan 1(printerFirmwareSerialPort:org.area515.resinprinter.serial.JSSCCommPort@f14b92, projectorSerialPort:org.area515.resinprinter.serial.JSSCCommPort@140c3f Display::0.0)
2016-01-26 05:10:02,107 INFO o.a.r.g.GCodeControl [qtp12042244-13] Write: G91

2016-01-26 05:10:31,780 DEBUG o.a.r.p.PrinterManager [qtp12042244-218] Attempting to stop printer:Titan 1(printerFirmwareSerialPort:org.area515.resinprinter.serial.JSSCCommPort@f14b92, projectorSerialPort:org.area515.resinprinter.serial.JSSCCommPort@140c3f Display::0.0)
2016-01-26 05:10:31,833 DEBUG o.a.r.p.PrinterManager [qtp12042244-218] Stopped printer:Titan 1(printerFirmwareSerialPort:org.area515.resinprinter.serial.JSSCCommPort@f14b92, projectorSerialPort:org.area515.resinprinter.serial.JSSCCommPort@140c3f Display::0.0)
2016-01-26 05:10:31,836 INFO o.a.r.s.SerialManager [qtp12042244-218] Removing serial assignments for printer:Titan 1(printerFirmwareSerialPort:org.area515.resinprinter.serial.JSSCCommPort@f14b92, projectorSerialPort:org.area515.resinprinter.serial.JSSCCommPort@140c3f Display::0.0)
2016-01-26 05:10:31,839 INFO o.a.r.s.SerialManager [qtp12042244-218] Removing firmware serialorg.area515.resinprinter.serial.JSSCCommPort@f14b92 assignment for printer:Titan 1(printerFirmwareSerialPort:org.area515.resinprinter.serial.JSSCCommPort@f14b92, projectorSerialPort:org.area515.resinprinter.serial.JSSCCommPort@140c3f Display::0.0)
2016-01-26 05:10:31,842 INFO o.a.r.p.Printer [qtp12042244-218] Firmware serial port set to:null
2016-01-26 05:10:31,844 INFO o.a.r.s.SerialManager [qtp12042244-218] Removing protector serial:org.area515.resinprinter.serial.JSSCCommPort@140c3f assignment for printer:Titan 1(printerFirmwareSerialPort:null, projectorSerialPort:org.area515.resinprinter.serial.JSSCCommPort@140c3f Display::0.0)
2016-01-26 05:10:31,847 INFO o.a.r.s.SerialManager [qtp12042244-218] Clearing up projector model from printer:Titan 1(printerFirmwareSerialPort:null, projectorSerialPort:null Display::0.0)
2016-01-26 05:10:31,827 ERROR o.a.r.g.GCodeControl [qtp12042244-13] Couldn't send:G91

java.io.IOException: Couldn't read bytes from serial port.

When the projector serial is explicitly set to /dev/ttyUSB1, the log shows normal firmware communication for the Z moves and no exceptions when the printer is stopped:

2016-01-26 05:11:25,912 INFO o.a.r.s.SerialManager [qtp12042244-218] Completed assignment of projector:Acer using serial
Port:org.area515.resinprinter.serial.JSSCCommPort@893059 with settings:{Port:/dev/ttyUSB1 speed:9600 databits:8 parity:N
one stopbits:One handshake:null} to printer:Titan 1(printerFirmwareSerialPort:org.area515.resinprinter.serial.JSSCCommPo
rt@6c28be, projectorSerialPort:org.area515.resinprinter.serial.JSSCCommPort@893059 Display::0.0)
2016-01-26 05:11:25,914 DEBUG o.a.r.p.PrinterManager [qtp12042244-218] Assigned projector:org.area515.resinprinter.seria
l.JSSCCommPort@893059 to:Titan 1(printerFirmwareSerialPort:org.area515.resinprinter.serial.JSSCCommPort@6c28be, projecto
rSerialPort:org.area515.resinprinter.serial.JSSCCommPort@893059 Display::0.0)
2016-01-26 05:11:25,915 INFO o.a.r.p.PrinterManager [qtp12042244-218] Printer started:Titan 1(printerFirmwareSerialPort:
org.area515.resinprinter.serial.JSSCCommPort@6c28be, projectorSerialPort:org.area515.resinprinter.serial.JSSCCommPort@89
3059 Display::0.0)
2016-01-26 05:11:31,352 INFO o.a.r.g.GCodeControl [qtp12042244-17] Write: G91

2016-01-26 05:11:31,655 INFO o.a.r.g.GCodeControl [qtp12042244-17] lineRead: ok

2016-01-26 05:11:31,659 INFO o.a.r.g.GCodeControl [qtp12042244-17] Write: G1 Z1.000

2016-01-26 05:11:31,962 INFO o.a.r.g.GCodeControl [qtp12042244-17] lineRead: ok

2016-01-26 05:11:36,299 INFO o.a.r.g.GCodeControl [qtp12042244-218] Write: G91

2016-01-26 05:11:36,602 INFO o.a.r.g.GCodeControl [qtp12042244-218] lineRead: ok

2016-01-26 05:11:36,607 INFO o.a.r.g.GCodeControl [qtp12042244-218] Write: G1 Z1.000

2016-01-26 05:11:36,910 INFO o.a.r.g.GCodeControl [qtp12042244-218] lineRead: ok

2016-01-26 05:11:45,094 DEBUG o.a.r.p.PrinterManager [qtp12042244-16] Attempting to stop printer:Titan 1(printerFirmwareSerialPort:org.area515.resinprinter.serial.JSSCCommPort@6c28be, projectorSerialPort:org.area515.resinprinter.serial.JSSCCommPort@893059 Display::0.0)
2016-01-26 05:11:45,114 DEBUG o.a.r.p.PrinterManager [qtp12042244-16] Stopped printer:Titan 1(printerFirmwareSerialPort:org.area515.resinprinter.serial.JSSCCommPort@6c28be, projectorSerialPort:org.area515.resinprinter.serial.JSSCCommPort@893059 Display::0.0)

LogBundle is attached:

LogBundle.zip

WesGilster commented 8 years ago

I think I see what is going on. ProjectorPort detection is attempting to roll through all of the serial ports including the Firmware port and sends a bunch of junk to it.That confuses the firmware and the rest is history. I'll try to fix tonight.

WesGilster commented 8 years ago

Fixed in development version cwh-0.210. I forgot to override equals and hashcode which meant serial reservations in the SerialManager weren't really working for org.area515.resinprinter.serial.JSSCCommPort.

jmkao commented 8 years ago

Awesome, confirmed that the fix works. Both firmware autodetect and manually set firmware ports work in conjunction with projector autodetect now.

Thanks!