001package jmri.jmrix.loconet;
002
003import java.util.NoSuchElementException;
004import org.slf4j.Logger;
005import org.slf4j.LoggerFactory;
006
007/**
008 * Converts Stream-based I/O to/from LocoNet messages. The "LocoNetInterface"
009 * side sends/receives LocoNetMessage objects. The connection to a
010 * LnPortController is via a pair of *Streams, which then carry sequences of
011 * characters for transmission.
012 * <p>
013 * Messages come to this via the main GUI thread, and are forwarded back to
014 * listeners in that same thread. Reception and transmission are handled in
015 * dedicated threads by RcvHandler and XmtHandler objects. Those are internal
016 * classes defined here. The thread priorities are:
017 * <ul>
018 * <li> RcvHandler - at highest available priority
019 * <li> XmtHandler - down one, which is assumed to be above the GUI
020 * <li> (everything else)
021 * </ul>
022 * Some of the message formats used in this class are Copyright Digitrax, Inc.
023 * and used with permission as part of the JMRI project. That permission does
024 * not extend to uses in other software products. If you wish to use this code,
025 * algorithm or these message formats outside of JMRI, please contact Digitrax
026 * Inc for separate permission.
027 *
028 * @author Bob Jacobsen Copyright (C) 2001, 2018
029 */
030public class LnPacketizerStrict extends LnPacketizer {
031
032    // waiting for this echo
033    private LocoNetMessage waitForMsg;
034    // waiting on LACK
035    private boolean waitingOnLack;
036    // wait this, CS gone busy
037    private int waitBusy;
038    // retry required, lost echo, bad IMM, general busy
039    private boolean reTryRequired;
040
041    static public int maxWaitCount = 150; // public for script access
042
043    public LnPacketizerStrict(LocoNetSystemConnectionMemo m) {
044        super(m);
045    }
046
047    /**
048     * Captive class to handle incoming characters. This is a permanent loop,
049     * looking for input messages in character form on the stream connected to
050     * the LnPortController via <code>connectPort</code>.
051     */
052    protected class RcvHandlerStrict implements Runnable {
053
054        /**
055         * Remember the LnPacketizer object.
056         */
057        LnTrafficController trafficController;
058
059        public RcvHandlerStrict(LnTrafficController lt) {
060            trafficController = lt;
061        }
062
063        /**
064         * Handle incoming characters. This is a permanent loop, looking for
065         * input messages in character form on the stream connected to the
066         * LnPortController via <code>connectPort</code>. Terminates with the
067         * input stream breaking out of the try block.
068         */
069        @Override
070        public void run() {
071            int opCode;
072            while (true) {  // loop permanently, program close will exit
073                try {
074                    // start by looking for command -  skip if bit not set
075                    while (((opCode = (readByteProtected(istream) & 0xFF)) & 0x80) == 0) {
076                        log.trace("Skipping: {}", Integer.toHexString(opCode)); // NOI18N
077                    }
078                    // here opCode is OK. Create output message
079                    if (log.isTraceEnabled()) {
080                        log.trace(" (RcvHandler) Start message with opcode: {}", Integer.toHexString(opCode)); // NOI18N
081                    }
082                    LocoNetMessage msg = null;
083                    while (msg == null) {
084                        try {
085                            // Capture 2nd byte, always present
086                            int byte2 = readByteProtected(istream) & 0xFF;
087                            if (log.isTraceEnabled()) {
088                                log.trace("Byte2: {}", Integer.toHexString(byte2)); // NOI18N
089                            }   // Decide length
090                            int len = 2;
091                            switch ((opCode & 0x60) >> 5) {
092                                case 0:
093                                    /* 2 byte message */
094                                    len = 2;
095                                    break;
096                                case 1:
097                                    /* 4 byte message */
098                                    len = 4;
099                                    break;
100                                case 2:
101                                    /* 6 byte message */
102                                    len = 6;
103                                    break;
104                                case 3:
105                                    /* N byte message */
106                                    if (byte2 < 2) {
107                                        log.error("LocoNet message length invalid: {} opcode: {}",
108                                                byte2, Integer.toHexString(opCode)); // NOI18N
109                                    }
110                                    len = byte2;
111                                    break;
112                                default:
113                                    log.warn("Unhandled code: {}", (opCode & 0x60) >> 5);
114                                    break;
115                            }
116                            msg = new LocoNetMessage(len);
117                            // message exists, now fill it
118                            msg.setOpCode(opCode);
119                            msg.setElement(1, byte2);
120                            log.trace("len: {}", len); // NOI18N
121                            for (int i = 2; i < len; i++) {
122                                // check for message-blocking error
123                                int b = readByteProtected(istream) & 0xFF;
124                                if (log.isTraceEnabled()) {
125                                    log.trace("char {} is: {}", i, Integer.toHexString(b)); // NOI18N
126                                }
127                                if ((b & 0x80) != 0) {
128                                    log.warn("LocoNet message with opCode: {} ended early. Expected length: {} seen length: {} unexpected byte: {}", Integer.toHexString(opCode), len, i, Integer.toHexString(b)); // NOI18N
129                                    opCode = b;
130                                    throw new LocoNetMessageException();
131                                }
132                                msg.setElement(i, b);
133                            }
134                        } catch (LocoNetMessageException e) {
135                            // retry by destroying the existing message
136                            // opCode is set for the newly-started packet
137                            msg = null;
138                        }
139                    }
140                    // check parity
141                    if (!msg.checkParity()) {
142                        log.warn("Ignore LocoNet packet with bad checksum: [{}]", msg.toString());  // NOI18N
143                        throw new LocoNetMessageException();
144                    }
145                    // message is complete, dispatch it !!
146                    {
147                        if (log.isDebugEnabled()) { // avoid String building if not needed
148                            log.debug("queue message for notification: {}", msg.toString());  // NOI18N
149                        }
150                        // check for XmtHandler waiting on return values
151                        if (waitForMsg != null) {
152                            if (waitForMsg.equals(msg)) {
153                                waitForMsg = null;
154                            }
155                        }
156                        if (waitingOnLack) {
157                            if (msg.getOpCode() == LnConstants.OPC_LONG_ACK) {
158                                waitingOnLack = false;
159                                // check bad IMM
160                                if ((msg.getElement(1) & 0xff) == 0x6d && (msg.getElement(2) & 0xff) == 0) {
161                                    reTryRequired = true;
162                                    waitBusy = 100;
163                                    log.warn("IMM Back off");  // NOI18N
164                                } else {
165                                    reTryRequired = false;
166                                }
167                            } else if (msg.getOpCode() == LnConstants.OPC_SL_RD_DATA) {
168                                waitingOnLack = false;
169                            } else if ( msg.getOpCode() == LnConstants.OPC_ALM_READ ) { // Extended slot status
170                                waitingOnLack = false;
171                            }
172                            // check for CS busy
173                        } else if (msg.getOpCode() == LnConstants.OPC_GPBUSY) {
174                            waitBusy = 100;
175                            log.warn("CS Busy Back off");  // NOI18N
176                            reTryRequired = true;
177                            // check for waiting on echo
178                        }
179                        jmri.util.ThreadingUtil.runOnLayoutEventually(new RcvMemo(msg, trafficController));
180                    }
181                    // done with this one
182                } catch (LocoNetMessageException e) {
183                    // just let it ride for now
184                    log.warn("run: unexpected LocoNetMessageException", e); // NOI18N
185                } catch (java.io.EOFException e) {
186                    // posted from idle port when enableReceiveTimeout used
187                    log.trace("EOFException, is LocoNet serial I/O using timeouts?"); // NOI18N
188                } catch (java.io.IOException e) {
189                    // fired when write-end of HexFile reaches end
190                    log.debug("IOException, should only happen with HexFile", e); // NOI18N
191                    log.info("End of file"); // NOI18N
192                    disconnectPort(controller);
193                    return;
194                } // normally, we don't catch RuntimeException, but in this
195                // permanently running loop it seems wise.
196                catch (RuntimeException e) {
197                    log.warn("run: unexpected Exception", e); // NOI18N
198                }
199            } // end of permanent loop
200        }
201    }
202
203    /**
204     * Captive class to notify of one message
205     */
206    private static class RcvMemo implements jmri.util.ThreadingUtil.ThreadAction {
207
208        public RcvMemo(LocoNetMessage msg, LnTrafficController trafficController) {
209            thisMsg = msg;
210            thisTc = trafficController;
211        }
212        LocoNetMessage thisMsg;
213        LnTrafficController thisTc;
214
215        /**
216         * {@inheritDoc}
217         */
218        @Override
219        public void run() {
220            thisTc.notify(thisMsg);
221        }
222    }
223
224    /**
225     * Captive class to handle transmission
226     */
227    class XmtHandlerStrict implements Runnable {
228
229        /**
230         * {@inheritDoc}
231         */
232        @Override
233        public void run() {
234            int waitCount;
235            while (true) { // loop permanently
236                // any input?
237                try {
238                    // get content; failure is a NoSuchElementException
239                    log.trace("check for input"); // NOI18N
240                    byte msg[] = null;
241                    synchronized (this) {
242                        msg = xmtList.removeFirst();
243                    }
244                    // input - now send
245                    try {
246                        if (ostream != null) {
247                            if (!controller.okToSend()) {
248                                log.debug("LocoNet port not ready to receive"); // NOI18N
249                            }
250                            if (log.isDebugEnabled()) { // avoid String building if not needed
251                                log.debug("start write to stream: {}", jmri.util.StringUtil.hexStringFromBytes(msg)); // NOI18N
252                            }
253                            // get it started
254                            reTryRequired = true;
255                            int reTryCount = 0;
256                            while (reTryRequired) {
257                                // assert its going to work
258                                reTryRequired = false;
259                                waitForMsg = new LocoNetMessage(msg);
260                                if ((msg[0] & 0x08) != 0) {
261                                    waitingOnLack = true;
262                                }
263                                while (waitBusy != 0) {
264                                    // we do it this way as during our sleep the waitBusy time can be reset
265                                    int waitTime = waitBusy;
266                                    waitBusy = 0;
267                                    //if (log.isDebugEnabled()) {
268                                    //    log.debug("waitBusy");
269                                    //}
270                                    // for now so we know how prevalent this is over a long time span
271                                    log.warn("Waitbusy");
272                                    try {
273                                        Thread.sleep(waitTime);
274                                    } catch (InterruptedException ee) {
275                                        log.warn("waitBusy sleep Interrupted", ee); // NOI18N
276                                    }
277                                }
278                                ostream.write(msg);
279                                ostream.flush();
280                                if (log.isTraceEnabled()) {
281                                    log.trace("end write to stream: {}", jmri.util.StringUtil.hexStringFromBytes(msg)); // NOI18N
282                                }
283                                // loop waiting for echo message and or LACK
284                                // minimal sleeps so as to exit fast
285                                waitCount = 0;
286                                // echo as really fast
287                                while ((waitForMsg != null) && waitCount < maxWaitCount) {
288                                    try {
289                                        Thread.sleep(1);
290                                    } catch (InterruptedException ee) {
291                                        log.error("waitForMsg sleep Interrupted", ee); // NOI18N
292                                    }
293                                    waitCount++;
294                                }
295                                // Oh my lost the echo...
296                                if (waitCount >= maxWaitCount) {
297                                    log.warn("Retry Send for Lost Packet [{}] Count[{}]", waitForMsg,
298                                                reTryCount); // NOI18N
299                                    if (reTryCount < 5) {
300                                        reTryRequired = true;
301                                        reTryCount++;
302                                    } else {
303                                        reTryRequired = false;
304                                        reTryCount = 0;
305                                        log.warn("Give up on lost packet");
306                                    }
307                                } else {
308                                    // LACKs / a response can be slow
309                                    while (waitingOnLack && waitCount < 3*maxWaitCount) {
310                                        try {
311                                            Thread.sleep(1);
312                                        } catch (InterruptedException ee) {
313                                            log.error("waitingOnLack sleep Interrupted", ee); // NOI18N
314                                        }
315                                        waitCount++;
316                                    }
317                                    // Oh my lost the LACK / response...
318                                    if (waitCount >= 3*maxWaitCount) {
319                                        try {
320                                            log.warn("Retry Send for Lost Response Count[{}]", reTryCount); // NOI18N
321                                        } catch (NullPointerException npe) {
322                                            log.warn("Retry Send for waitingOnLack null?  Count[{}]", reTryCount); // NOI18N
323                                        }
324                                        if (reTryCount < 5) {
325                                            reTryRequired = true;
326                                            reTryCount++;
327                                        } else {
328                                            log.warn("Give up on Lost Response."); // NOI18N
329                                            reTryRequired = false;
330                                            reTryCount = 0;
331                                        }
332                                    }
333                                }
334                            }
335                            messageTransmitted(msg);
336                        } else {
337                            // no stream connected
338                            log.warn("sendLocoNetMessage: no connection established"); // NOI18N
339                        }
340                    } catch (java.io.IOException e) {
341                        log.warn("sendLocoNetMessage: IOException: {}", e.toString()); // NOI18N
342                    }
343                } catch (NoSuchElementException e) {
344                    // message queue was empty, wait for input
345                    log.trace("start wait"); // NOI18N
346                    new jmri.util.WaitHandler(this); // handle synchronization, spurious wake, interruption
347                    log.trace("end wait"); // NOI18N
348                }
349            }
350        }
351    }
352
353
354    /**
355     * Invoked at startup to start the threads needed here.
356     */
357    @Override
358    public void startThreads() {
359        int priority = Thread.currentThread().getPriority();
360        log.debug("startThreads current priority = {} max available = {} default = {} min available = {}", // NOI18N
361                priority, Thread.MAX_PRIORITY, Thread.NORM_PRIORITY, Thread.MIN_PRIORITY);
362
363        // make sure that the xmt priority is no lower than the current priority
364        int xmtpriority = (Thread.MAX_PRIORITY - 1 > priority ? Thread.MAX_PRIORITY - 1 : Thread.MAX_PRIORITY);
365        // start the XmtHandler in a thread of its own
366        if (xmtHandler == null) {
367            xmtHandler = new XmtHandlerStrict();
368        }
369        xmtThread = new Thread(xmtHandler, "LocoNet transmit handler"); // NOI18N
370        log.debug("Xmt thread starts at priority {}", xmtpriority); // NOI18N
371        xmtThread.setDaemon(true);
372        xmtThread.setPriority(Thread.MAX_PRIORITY - 1);
373        xmtThread.start();
374
375        // start the RcvHandler in a thread of its own
376        if (rcvHandler == null) {
377            rcvHandler = new RcvHandlerStrict(this);
378        }
379        rcvThread = new Thread(rcvHandler, "LocoNet receive handler"); // NOI18N
380        rcvThread.setDaemon(true);
381        rcvThread.setPriority(Thread.MAX_PRIORITY);
382        rcvThread.start();
383
384        log.info("Strict Packetizer in use");
385
386    }
387
388    private final static Logger log = LoggerFactory.getLogger(LnPacketizerStrict.class);
389
390}