Executive summary ================= The NAL9602 experienced repeated serial timeouts that prevented Tethys from communicating with TethysDash or the operators. These errors were initially spotted on the freewave session _after_ we returned from deploying the vehicle.The problem began as we were putting the vehicle on the Paragon, but after passing all pre-deployment checks. 25 minutes after the _second_ 2-hour timeout in Default.xml, the NAL9602 was finally power cycled. It initialized fine 11 seconds after powering back up. It failed to initiate the next SBD session, which it only tried to do 22 minutes after reinitializing. 50 minutes later, it finally made a successful transaction, we were already on the Paragon leaving the mouth of Moss Landing harbor. The logs indicate that the vehicle did not attempt to power cycle the NAL9602, or mark it as failed, at any time during the 4 hours the driver was returning serial timeouts. 20130909T171827 =============== This set of logs was during pre-deployment checklist section 2 -- it starts with the reboot after `e2fsck`. The main actions are the burnwire check, the primary battery voltage check, and the clock check. These logs are terminated with the use of `Tools/on-tether.sh tethys` at checklist point 2.8 20130909T173942 =============== These logs start at part 3 of the pre-deployment checklist, when you reboot from the linux terminal at checklist point 3.2 This will _always_ produce a fault condition like: 2013/09/09 10:39:53.593 logFault, [CBIT] LAST RESTART WAS UNINTENTIONAL. A `restart hardware` is required to clear that flag, and there is no `restart hardware` currently in the checklist sequence. (I would suggest that we insert a `restart hardware` right after the `reboot` and before the SBIT pass and `failc` checks if we are going to add one anywhere.) Faults on startup ----------------- When this logset started, there were several faults that are _normal_: * 2013-09-09T17:39:56.217Z,1378748396.217 [BuoyancyServo](FAULT): Buoyancy failed to initialize * 2013-09-09T17:40:04.558Z,1378748404.558 [Aanderaa_O2](FAULT): Timed out starting * [NAL9602] GPS failed to acquire within timeout. Each of these faults was resolved: * 2013-09-09T17:39:58.868Z,1378748398.868 [CBIT](INFO): Clearing failed state for component BuoyancyServo * 2013-09-09T17:40:06.132Z,1378748406.132 [CBIT](INFO): Clearing failed state for component Aanderaa_O2 * 2013-09-09T17:55:03.812Z,1378749303.812 [NAL9602](IMPORTANT): GPS fix at: 1378749302.00 Iridium ------- ### Preparation Thomas rolled Tethys out into the parking lot ~17:52 UTC. I started IBIT via freewave once he returned to lab (17:54 UTC). ### IBIT Comms Status 2013-09-09T17:56:20.896Z,1378749380.896 [IBIT](IMPORTANT): Communications Status: Fix Status: 1 Iridium Signal Strength: 1 Latitude: 36.802544 Longitude: -121.787552 2013-09-09T17:59:19.391Z,1378749559.391 [IBIT](IMPORTANT): Communications Status: Fix Status: 1 Iridium Signal Strength: 2 Latitude: 36.802544 Longitude: -121.787552 ### Intervening time Sometime between 17:59 UTC and 18:06 UTC, Thomas and I left the lab to roll Tethys down to the Paragon. During that time, Tethys successfully sent N SBDs -- MOMSN 16056 to 16059. On MOMSN 16060, she didn't get a good connection: 2013-09-09T18:00:08.506Z,1378749608.506 [NAL9602](INFO): SBD MO Status=2, MOMSN=16060, MT Status=2, MTMSN=0 2013-09-09T18:00:08.506Z,1378749608.506 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 Five minutes later, there were two more failed SBD sessions, but a good GPS fix: 2013-09-09T18:05:26.990Z,1378749926.990 [NAL9602](INFO): Powering up 2013-09-09T18:05:37.819Z,1378749937.819 [NAL9602](INFO): NAL9602 initialized 2013-09-09T18:05:52.113Z,1378749952.113 [NAL9602](INFO): SBD MO Status=2, MOMSN=16061, MT Status=2, MTMSN=0 2013-09-09T18:05:52.113Z,1378749952.113 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2013-09-09T18:06:12.675Z,1378749972.675 [NAL9602](INFO): SBD MO Status=2, MOMSN=16061, MT Status=2, MTMSN=0 2013-09-09T18:06:12.675Z,1378749972.675 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2013-09-09T18:06:13.882Z,1378749973.882 [NAL9602](IMPORTANT): GPS fix at: 1378749972.00 ### NAL9602 serial timeout Several seconds later, the NAL9602 driver returned several more failures: 2013-09-09T18:06:22.079Z,1378749982.079 [NAL9602](INFO): SBD MO Status=2, MOMSN=16061, MT Status=2, MTMSN=0 2013-09-09T18:06:22.079Z,1378749982.079 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2013-09-09T18:07:38.180Z,1378750058.180 [NAL9602](ERROR): Verify xmit timeout failure. 2013-09-09T18:07:39.020Z,1378750059.020 [NAL9602](ERROR): Fill buffer uart error: serial timeout 2013-09-09T18:07:39.020Z,1378750059.020 [NAL9602](ERROR): Failed to receive READY. Modem reported: 2013-09-09T18:08:10.461Z,1378750090.461 [NAL9602](ERROR): Queried for signal strength and failed to receive response. serial timeout 2013-09-09T18:08:42.075Z,1378750122.075 [NAL9602](ERROR): Queried for signal strength and failed to receive response. serial timeout These serial timeouts continue for two hours with no other entries in the syslog. (We actually spotted them on the freewave terminal once we returned from deployment.) 2013-09-09T20:04:50.860Z,1378757090.860 [NAL9602](ERROR): Queried for signal strength and failed to receive response. serial timeout 2013-09-09T20:05:22.397Z,1378757122.397 [NAL9602](ERROR): Queried for signal strength and failed to receive response. serial timeout ### Communications timeout and weight drop After two hours of serial timeouts on the NAL9602, the Default mission timed out and burned the wire for the dropweight. 2013-09-09T20:05:26.355Z,1378757126.355 [Default:Iridium:Read_Iridium](INFO): Timed out from 2013-09-09T18:05:26.3Z 2013-09-09T20:05:26.356Z,1378757126.356 [Default:Iridium:Read_Iridium:A_Timeout] Running Loop=1 2013-09-09T20:05:26.356Z,1378757126.356 [Default:Iridium:Read_Iridium:A_Timeout](INFO): Aggregate::initialize Default:Iridium:Read_Iridium:A_Timeout 2013-09-09T20:05:26.356Z,1378757126.356 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute] Running Loop=1 2013-09-09T20:05:26.356Z,1378757126.356 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](INFO): Executing command Burn 300 2013-09-09T20:05:26.363Z,1378757126.363 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute] Stopped 2013-09-09T20:05:26.363Z,1378757126.363 [Default:Iridium:Read_Iridium:A_Timeout:B] Running Loop=1 2013-09-09T20:05:26.370Z,1378757126.370 [CommandLine](IMPORTANT): got command burn 300.000000 2013-09-09T20:05:26.745Z,1378757126.745 [Default:Iridium:Read_Iridium:A_Timeout:B](CRITICAL): Dropped drop weight due to communications timeout 2013-09-09T20:05:26.747Z,1378757126.747 [Default:Iridium:Read_Iridium:A_Timeout:B] Stopped 2013-09-09T20:05:26.747Z,1378757126.747 [Default:Iridium:Read_Iridium:A_Timeout](INFO): Completed Default:Iridium:Read_Iridium:A_Timeout 2013-09-09T20:05:26.748Z,1378757126.748 [Default:Iridium:Read_Iridium] Stopped The serial timeout problem persisted, though Tethys was getting good GPS fixes from the NAL9602. 2013-09-09T20:05:53.913Z,1378757153.913 [NAL9602](ERROR): Queried for signal strength and failed to receive response. serial timeout 2013-09-09T20:05:55.136Z,1378757155.136 [NAL9602](IMPORTANT): GPS fix at: 1378757154.00 The vehicle continued trying to call, and initiated a new dropweight burn again two hours later. 2013-09-09T22:05:37.383Z,1378764337.383 [CommandLine](IMPORTANT): got command burn 300.000000 The serial timeout persisted: 2013-09-09T22:05:48.188Z,1378764348.188 [NAL9602](ERROR): Queried for signal strength and failed to receive response. serial timeout The NAL9602 was finally powered down: 2013-09-09T22:05:53.845Z,1378764353.845 [NAL9602](INFO): Powering down The vehicle _never attempted to power cycle the NAL9602 during the two hours before burning the dropweight_. The two hour timeout is at the mission level `` in a `ReadDatum` block with ``. When it came back up, it failed to initiate a SBD session: 2013-09-09T22:06:31.883Z,1378764391.883 [NAL9602](INFO): Powering up 2013-09-09T22:06:42.496Z,1378764402.496 [NAL9602](INFO): NAL9602 initialized 2013-09-09T22:07:04.726Z,1378764424.726 [NAL9602](INFO): SBD MO Status=2, MOMSN=16061, MT Status=2, MTMSN=0 2013-09-09T22:07:04.726Z,1378764424.726 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 And there was a serial timeout on ThrusterServo (unrelated?) The Freewave was also power cycled several times. The NAL9602 finally made a successful transaction: 2013-09-09T22:07:55.436Z,1378764475.436 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=16061, MT Status=1, MTMSN=1142 2013-09-09T22:07:55.490Z,1378764475.490 [NAL9602](INFO): Sent 203 bytes from file Logs/20130909T173942/Courier0004.lzma 2013-09-09T22:07:55.490Z,1378764475.490 [NAL9602](INFO): Packets left to send: 0 2013-09-09T22:07:55.495Z,1378764475.495 [NAL9602](INFO): Stored copy of sent data in Logs/20130909T173942/Courier0004.lzma.parts/0000.sbd 2013-09-09T22:07:55.974Z,1378764475.974 [NAL9602](INFO): Received command:restart application The CommandLine never got the `restart application` command. Instead, the NAL got the next message and the CommandLine executed that: 2013-09-09T22:08:35.385Z,1378764515.385 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=16062, MT Status=1, MTMSN=1143 2013-09-09T22:08:35.432Z,1378764515.432 [NAL9602](INFO): Sent 332 bytes from file Logs/20130909T173942/Express0005.lzma 2013-09-09T22:08:35.432Z,1378764515.432 [NAL9602](INFO): Packets left to send: 3 2013-09-09T22:08:35.435Z,1378764515.435 [NAL9602](INFO): Stored copy of sent data in Logs/20130909T173942/Express0005.lzma.parts/0003.sbd 2013-09-09T22:08:36.093Z,1378764516.093 [NAL9602](INFO): Received command:load Science/science_to.xml;set science_to.YoYoMaxDepth 65 meter;set science_to.Wpt1Lat 36.9 degree;set science_to.Wpt1Lon -121.95 degree;set science_to.NeedCommsTime 60 minute;set science_to.Timeout 6 hour;run 2013-09-09T22:08:36.107Z,1378764516.107 [CommandLine](IMPORTANT): got command load ./Missions/Science/science_to.xml 2013-09-09T22:08:36.109Z,1378764516.109 [MissionManager](INFO): Loading Mission: ./Missions/Science/science_to.xml It then failed to initiate 8 more SBD sessions before sending 3 more SBDs. The CommandLine never acknowledged receipt of, or executed, the command `run`