2014-04-21T17:58:38.763Z,1398103118.763 [CommandLine](IMPORTANT): got command restart logs
2014-04-21T17:58:52.253Z,1398103132.253 [NAL9602](INFO): SBD MO Status=1, MOMSN=28186, MT Status=0, MTMSN=0
2014-04-21T17:58:52.304Z,1398103132.304 [NAL9602](INFO): Sent 45 bytes from file Logs/20140421T083939/Courier0148.lzma
2014-04-21T17:58:52.304Z,1398103132.304 [NAL9602](INFO): Packets left to send: 0
2014-04-21T17:58:52.306Z,1398103132.306 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T083939/Courier0148.lzma.parts/0000.sbd
2014-04-21T17:58:52.306Z,1398103132.306 [NAL9602](INFO): Completed sending Logs/20140421T083939/Courier0148.lzma
2014-04-21T17:59:08.133Z,1398103148.133 [NAL9602](INFO): SBD MO Status=2, MOMSN=28187, MT Status=2, MTMSN=0
2014-04-21T17:59:08.133Z,1398103148.133 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T17:59:09.459Z,1398103149.459 [NAL9602](IMPORTANT): GPS fix at: 1398103128.00
2014-04-21T17:59:09.507Z,1398103149.507 [Default:GPS:Read_GPS] Stopped
2014-04-21T17:59:09.507Z,1398103149.507 [Default:GPS:D] Running Loop=1
2014-04-21T17:59:09.951Z,1398103149.951 [Default:GPS:D] Stopped
2014-04-21T17:59:09.952Z,1398103149.952 [Default:GPS](INFO): Completed Default:GPS
2014-04-21T17:59:09.952Z,1398103149.952 [Default:GPS] Stopped
2014-04-21T17:59:09.952Z,1398103149.952 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-21T17:59:09.952Z,1398103149.952 [Default:GPS:A.SetSpeed] Stopped
2014-04-21T17:59:09.952Z,1398103149.952 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T17:59:26.671Z,1398103166.671 [NAL9602](INFO): SBD MO Status=1, MOMSN=28187, MT Status=0, MTMSN=0
2014-04-21T17:59:26.721Z,1398103166.721 [NAL9602](INFO): Sent 105 bytes from file Logs/20140421T083939/Express0145.lzma
2014-04-21T17:59:26.721Z,1398103166.721 [NAL9602](INFO): Packets left to send: 0
2014-04-21T17:59:26.723Z,1398103166.723 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T083939/Express0145.lzma.parts/0000.sbd
2014-04-21T17:59:26.724Z,1398103166.724 [NAL9602](INFO): Completed sending Logs/20140421T083939/Express0145.lzma
2014-04-21T17:59:35.159Z,1398103175.159 [NAL9602](INFO): SBD MO Status=1, MOMSN=28188, MT Status=0, MTMSN=0
2014-04-21T17:59:35.206Z,1398103175.206 [NAL9602](INFO): Sent 124 bytes from file Logs/20140421T083939/Express0149.lzma
2014-04-21T17:59:35.207Z,1398103175.207 [NAL9602](INFO): Packets left to send: 0
2014-04-21T17:59:35.208Z,1398103175.208 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T083939/Express0149.lzma.parts/0000.sbd
2014-04-21T17:59:35.209Z,1398103175.209 [NAL9602](INFO): Completed sending Logs/20140421T083939/Express0149.lzma
2014-04-21T17:59:45.180Z,1398103185.180 [NAL9602](INFO): SBD MO Status=0, MOMSN=28189, MT Status=0, MTMSN=0
2014-04-21T18:00:02.331Z,1398103202.331 [NAL9602](INFO): SBD MO Status=1, MOMSN=28190, MT Status=0, MTMSN=0
2014-04-21T18:00:02.385Z,1398103202.385 [NAL9602](INFO): Sent 296 bytes from file Logs/20140421T175838/Courier0000.lzma
2014-04-21T18:00:02.385Z,1398103202.385 [NAL9602](INFO): Packets left to send: 0
2014-04-21T18:00:02.386Z,1398103202.386 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Courier0000.lzma.parts/0000.sbd
2014-04-21T18:00:02.387Z,1398103202.387 [NAL9602](INFO): Completed sending Logs/20140421T175838/Courier0000.lzma
2014-04-21T18:00:12.393Z,1398103212.393 [NAL9602](INFO): SBD MO Status=1, MOMSN=28191, MT Status=0, MTMSN=0
2014-04-21T18:00:12.444Z,1398103212.444 [NAL9602](INFO): Sent 332 bytes from file Logs/20140421T175838/Express0001.lzma
2014-04-21T18:00:12.444Z,1398103212.444 [NAL9602](INFO): Packets left to send: 1
2014-04-21T18:00:12.448Z,1398103212.448 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Express0001.lzma.parts/0001.sbd
2014-04-21T18:00:18.783Z,1398103218.783 [NAL9602](INFO): SBD MO Status=1, MOMSN=28192, MT Status=0, MTMSN=0
2014-04-21T18:00:18.850Z,1398103218.850 [NAL9602](INFO): Sent 29 bytes from file Logs/20140421T175838/Express0001.lzma
2014-04-21T18:00:18.850Z,1398103218.850 [NAL9602](INFO): Packets left to send: 0
2014-04-21T18:00:18.851Z,1398103218.851 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Express0001.lzma.parts/0000.sbd
2014-04-21T18:00:18.852Z,1398103218.852 [NAL9602](INFO): Completed sending Logs/20140421T175838/Express0001.lzma
2014-04-21T18:00:29.647Z,1398103229.647 [NAL9602](INFO): SBD MO Status=0, MOMSN=28193, MT Status=0, MTMSN=0
2014-04-21T18:00:29.744Z,1398103229.744 [Default:Iridium:Read_Iridium] Stopped
2014-04-21T18:00:29.744Z,1398103229.744 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-21T18:00:29.744Z,1398103229.744 [Default:Iridium] Stopped
2014-04-21T18:00:29.744Z,1398103229.744 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-21T18:00:29.745Z,1398103229.745 [Default:Iridium:A.SetSpeed] Stopped
2014-04-21T18:00:29.745Z,1398103229.745 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T18:00:30.164Z,1398103230.164 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-21T18:00:30.164Z,1398103230.164 [Default:CallIridium:B] Stopped
2014-04-21T18:00:30.164Z,1398103230.164 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-21T18:00:30.164Z,1398103230.164 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-21T18:00:30.164Z,1398103230.164 [Default:CallIridium] Stopped
2014-04-21T18:00:30.164Z,1398103230.164 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-21T18:00:40.314Z,1398103240.314 [NAL9602](INFO): Powering down
2014-04-21T18:04:30.257Z,1398103470.257 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-04-21T18:04:40.304Z,1398103480.304 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-04-21T18:04:45.269Z,1398103485.269 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-04-21T18:04:50.268Z,1398103490.268 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-04-21T18:04:55.281Z,1398103495.281 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-04-21T18:05:00.272Z,1398103500.272 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-04-21T18:05:05.267Z,1398103505.267 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-04-21T18:05:10.271Z,1398103510.271 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-04-21T18:05:15.267Z,1398103515.267 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-04-21T18:05:20.267Z,1398103520.267 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-04-21T18:05:25.274Z,1398103525.274 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-04-21T18:05:30.313Z,1398103530.313 [Default:CallIridium] Running Loop=1
2014-04-21T18:05:30.313Z,1398103530.313 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-21T18:05:30.313Z,1398103530.313 [Default:CallIridium:A] Running Loop=1
2014-04-21T18:05:30.314Z,1398103530.314 [Default:CallIridium:A] Stopped
2014-04-21T18:05:30.314Z,1398103530.314 [Default:CallIridium:B] Running Loop=1
2014-04-21T18:05:30.314Z,1398103530.314 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-21T18:05:35.258Z,1398103535.258 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-04-21T18:05:35.313Z,1398103535.313 [Default:Iridium] Running Loop=1
2014-04-21T18:05:35.313Z,1398103535.313 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-21T18:05:35.313Z,1398103535.313 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-21T18:05:35.313Z,1398103535.313 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-21T18:05:35.313Z,1398103535.313 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-21T18:05:35.314Z,1398103535.314 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T18:05:35.314Z,1398103535.314 [Default:Iridium:B.GoToSurface] Stopped
2014-04-21T18:05:35.314Z,1398103535.314 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-21T18:05:35.314Z,1398103535.314 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-21T18:05:35.315Z,1398103535.315 [Default:GPS] Running Loop=1
2014-04-21T18:05:35.315Z,1398103535.315 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-21T18:05:35.315Z,1398103535.315 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-21T18:05:35.315Z,1398103535.315 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-21T18:05:35.315Z,1398103535.315 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-21T18:05:35.315Z,1398103535.315 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T18:05:35.320Z,1398103535.320 [Default:GPS:B.GoToSurface] Stopped
2014-04-21T18:05:35.320Z,1398103535.320 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-21T18:05:35.321Z,1398103535.321 [Default:GPS:Read_GPS] Running Loop=1
2014-04-21T18:05:36.339Z,1398103536.339 [NAL9602](INFO): Powering up
2014-04-21T18:05:47.083Z,1398103547.083 [NAL9602](INFO): NAL9602 initialized
2014-04-21T18:06:13.152Z,1398103573.152 [NAL9602](INFO): SBD MO Status=1, MOMSN=28194, MT Status=0, MTMSN=0
2014-04-21T18:06:13.203Z,1398103573.203 [NAL9602](INFO): Sent 45 bytes from file Logs/20140421T175838/Courier0004.lzma
2014-04-21T18:06:13.204Z,1398103573.204 [NAL9602](INFO): Packets left to send: 0
2014-04-21T18:06:13.205Z,1398103573.205 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Courier0004.lzma.parts/0000.sbd
2014-04-21T18:06:13.206Z,1398103573.206 [NAL9602](INFO): Completed sending Logs/20140421T175838/Courier0004.lzma
2014-04-21T18:06:20.311Z,1398103580.311 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items. Got 44 of 46
2014-04-21T18:06:20.311Z,1398103580.311 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 1 1 1 1 38.8 44.0 39.8 35.8 -856.0 -172.4 711.9 -4.5 -924 -162 697 -76 10 12 10 8 -2092.6 -224.1 -86.6 1 518.6 -2038.1 -120.8 1 -2163 -114 -125 2 403 -2128 -125 2 -9.28 -1.96 97.7 35.8 16.9 0.00589 81
2014-04-21T18:06:32.102Z,1398103592.102 [NAL9602](INFO): SBD MO Status=2, MOMSN=28195, MT Status=2, MTMSN=0
2014-04-21T18:06:32.102Z,1398103592.102 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T18:07:04.438Z,1398103624.438 [NAL9602](INFO): SBD MO Status=1, MOMSN=28195, MT Status=0, MTMSN=0
2014-04-21T18:07:04.491Z,1398103624.491 [NAL9602](INFO): Sent 70 bytes from file Logs/20140421T175838/Express0005.lzma
2014-04-21T18:07:04.491Z,1398103624.491 [NAL9602](INFO): Packets left to send: 0
2014-04-21T18:07:04.493Z,1398103624.493 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Express0005.lzma.parts/0000.sbd
2014-04-21T18:07:04.493Z,1398103624.493 [NAL9602](INFO): Completed sending Logs/20140421T175838/Express0005.lzma
2014-04-21T18:07:20.442Z,1398103640.442 [NAL9602](INFO): SBD MO Status=2, MOMSN=28196, MT Status=2, MTMSN=0
2014-04-21T18:07:20.442Z,1398103640.442 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T18:07:21.786Z,1398103641.786 [NAL9602](IMPORTANT): GPS fix at: 1398103620.00
2014-04-21T18:07:21.800Z,1398103641.800 [DeadReckonUsingMultipleVelocitySources](DEBUG): horizontalPathLengthSinceLastFix_ = 933.444, recording fix residuals...
2014-04-21T18:07:21.805Z,1398103641.805 [UniversalFixResidualReporter](DEBUG): Fix parameters were touched since the last run.
2014-04-21T18:07:21.806Z,1398103641.806 [UniversalFixResidualReporter](IMPORTANT): Fix residual: 5.7 %DT, over the last 902.8 m. Residual distance 53.6 m at bearing 21.8 degrees. Fix at (33.5892, -117.8956) with 902.8 m made good.
2014-04-21T18:07:21.808Z,1398103641.808 [Default:GPS:Read_GPS] Stopped
2014-04-21T18:07:21.808Z,1398103641.808 [Default:GPS:D] Running Loop=1
2014-04-21T18:07:22.285Z,1398103642.285 [Default:GPS:D] Stopped
2014-04-21T18:07:22.285Z,1398103642.285 [Default:GPS](INFO): Completed Default:GPS
2014-04-21T18:07:22.285Z,1398103642.285 [Default:GPS] Stopped
2014-04-21T18:07:22.286Z,1398103642.286 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-21T18:07:22.286Z,1398103642.286 [Default:GPS:A.SetSpeed] Stopped
2014-04-21T18:07:22.286Z,1398103642.286 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T18:07:25.901Z,1398103645.901 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2014-04-21T18:07:36.897Z,1398103656.897 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2014-04-21T18:07:52.955Z,1398103672.955 [NAL9602](INFO): SBD MO Status=0, MOMSN=28196, MT Status=0, MTMSN=0
2014-04-21T18:07:53.041Z,1398103673.041 [Default:Iridium:Read_Iridium] Stopped
2014-04-21T18:07:53.042Z,1398103673.042 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-21T18:07:53.042Z,1398103673.042 [Default:Iridium] Stopped
2014-04-21T18:07:53.042Z,1398103673.042 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-21T18:07:53.042Z,1398103673.042 [Default:Iridium:A.SetSpeed] Stopped
2014-04-21T18:07:53.042Z,1398103673.042 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T18:07:53.468Z,1398103673.468 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-21T18:07:53.468Z,1398103673.468 [Default:CallIridium:B] Stopped
2014-04-21T18:07:53.468Z,1398103673.468 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-21T18:07:53.468Z,1398103673.468 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-21T18:07:53.469Z,1398103673.469 [Default:CallIridium] Stopped
2014-04-21T18:07:53.469Z,1398103673.469 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-21T18:08:03.582Z,1398103683.582 [NAL9602](INFO): Powering down
2014-04-21T18:12:53.619Z,1398103973.619 [Default:CallIridium] Running Loop=1
2014-04-21T18:12:53.619Z,1398103973.619 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-21T18:12:53.620Z,1398103973.620 [Default:CallIridium:A] Running Loop=1
2014-04-21T18:12:53.620Z,1398103973.620 [Default:CallIridium:A] Stopped
2014-04-21T18:12:53.620Z,1398103973.620 [Default:CallIridium:B] Running Loop=1
2014-04-21T18:12:53.621Z,1398103973.621 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-21T18:12:58.604Z,1398103978.604 [Default:Iridium] Running Loop=1
2014-04-21T18:12:58.604Z,1398103978.604 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-21T18:12:58.604Z,1398103978.604 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-21T18:12:58.604Z,1398103978.604 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-21T18:12:58.604Z,1398103978.604 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-21T18:12:58.604Z,1398103978.604 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T18:12:58.605Z,1398103978.605 [Default:Iridium:B.GoToSurface] Stopped
2014-04-21T18:12:58.605Z,1398103978.605 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-21T18:12:58.605Z,1398103978.605 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-21T18:12:58.606Z,1398103978.606 [Default:GPS] Running Loop=1
2014-04-21T18:12:58.606Z,1398103978.606 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-21T18:12:58.606Z,1398103978.606 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-21T18:12:58.606Z,1398103978.606 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-21T18:12:58.606Z,1398103978.606 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-21T18:12:58.606Z,1398103978.606 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T18:12:58.607Z,1398103978.607 [Default:GPS:B.GoToSurface] Stopped
2014-04-21T18:12:58.607Z,1398103978.607 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-21T18:12:58.607Z,1398103978.607 [Default:GPS:Read_GPS] Running Loop=1
2014-04-21T18:12:59.676Z,1398103979.676 [NAL9602](INFO): Powering up
2014-04-21T18:13:10.458Z,1398103990.458 [NAL9602](INFO): NAL9602 initialized
2014-04-21T18:14:01.666Z,1398104041.666 [NAL9602](INFO): SBD MO Status=2, MOMSN=28197, MT Status=2, MTMSN=0
2014-04-21T18:14:01.666Z,1398104041.666 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T18:14:29.652Z,1398104069.652 [NAL9602](IMPORTANT): GPS fix at: 1398104049.00
2014-04-21T18:14:29.667Z,1398104069.667 [DeadReckonUsingMultipleVelocitySources](DEBUG): horizontalPathLengthSinceLastFix_ = 895.926, recording fix residuals...
2014-04-21T18:14:29.671Z,1398104069.671 [UniversalFixResidualReporter](DEBUG): Fix parameters were touched since the last run.
2014-04-21T18:14:29.672Z,1398104069.672 [UniversalFixResidualReporter](IMPORTANT): Fix residual: 4.1 %DT, over the last 878.4 m. Residual distance 36.9 m at bearing 23.2 degrees. Fix at (33.5874, -117.8864) with 878.4 m made good.
2014-04-21T18:14:29.694Z,1398104069.694 [Default:GPS:Read_GPS] Stopped
2014-04-21T18:14:29.694Z,1398104069.694 [Default:GPS:D] Running Loop=1
2014-04-21T18:14:30.169Z,1398104070.169 [Default:GPS:D] Stopped
2014-04-21T18:14:30.170Z,1398104070.170 [Default:GPS](INFO): Completed Default:GPS
2014-04-21T18:14:30.170Z,1398104070.170 [Default:GPS] Stopped
2014-04-21T18:14:30.170Z,1398104070.170 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-21T18:14:30.170Z,1398104070.170 [Default:GPS:A.SetSpeed] Stopped
2014-04-21T18:14:30.170Z,1398104070.170 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T18:15:18.124Z,1398104118.124 [NAL9602](INFO): SBD MO Status=2, MOMSN=28197, MT Status=2, MTMSN=0
2014-04-21T18:15:18.124Z,1398104118.124 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T18:15:40.706Z,1398104140.706 [NAL9602](INFO): SBD MO Status=1, MOMSN=28197, MT Status=0, MTMSN=0
2014-04-21T18:15:40.759Z,1398104140.759 [NAL9602](INFO): Sent 76 bytes from file Logs/20140421T175838/Courier0008.lzma
2014-04-21T18:15:40.760Z,1398104140.760 [NAL9602](INFO): Packets left to send: 0
2014-04-21T18:15:40.761Z,1398104140.761 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Courier0008.lzma.parts/0000.sbd
2014-04-21T18:15:40.761Z,1398104140.761 [NAL9602](INFO): Completed sending Logs/20140421T175838/Courier0008.lzma
2014-04-21T18:15:55.928Z,1398104155.928 [NAL9602](INFO): SBD MO Status=1, MOMSN=28198, MT Status=0, MTMSN=0
2014-04-21T18:15:55.983Z,1398104155.983 [NAL9602](INFO): Sent 269 bytes from file Logs/20140421T175838/Express0009.lzma
2014-04-21T18:15:55.983Z,1398104155.983 [NAL9602](INFO): Packets left to send: 0
2014-04-21T18:15:55.986Z,1398104155.986 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Express0009.lzma.parts/0000.sbd
2014-04-21T18:15:55.986Z,1398104155.986 [NAL9602](INFO): Completed sending Logs/20140421T175838/Express0009.lzma
2014-04-21T18:16:08.578Z,1398104168.578 [NAL9602](INFO): SBD MO Status=0, MOMSN=28199, MT Status=0, MTMSN=0
2014-04-21T18:16:08.677Z,1398104168.677 [Default:Iridium:Read_Iridium] Stopped
2014-04-21T18:16:08.678Z,1398104168.678 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-21T18:16:08.678Z,1398104168.678 [Default:Iridium] Stopped
2014-04-21T18:16:08.679Z,1398104168.679 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-21T18:16:08.679Z,1398104168.679 [Default:Iridium:A.SetSpeed] Stopped
2014-04-21T18:16:08.679Z,1398104168.679 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T18:16:09.126Z,1398104169.126 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-21T18:16:09.126Z,1398104169.126 [Default:CallIridium:B] Stopped
2014-04-21T18:16:09.126Z,1398104169.126 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-21T18:16:09.126Z,1398104169.126 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-21T18:16:09.126Z,1398104169.126 [Default:CallIridium] Stopped
2014-04-21T18:16:09.126Z,1398104169.126 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-21T18:16:19.227Z,1398104179.227 [NAL9602](INFO): Powering down
2014-04-21T18:21:09.271Z,1398104469.271 [Default:CallIridium] Running Loop=1
2014-04-21T18:21:09.271Z,1398104469.271 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-21T18:21:09.271Z,1398104469.271 [Default:CallIridium:A] Running Loop=1
2014-04-21T18:21:09.271Z,1398104469.271 [Default:CallIridium:A] Stopped
2014-04-21T18:21:09.272Z,1398104469.272 [Default:CallIridium:B] Running Loop=1
2014-04-21T18:21:09.272Z,1398104469.272 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-21T18:21:14.236Z,1398104474.236 [Default:Iridium] Running Loop=1
2014-04-21T18:21:14.236Z,1398104474.236 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-21T18:21:14.236Z,1398104474.236 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-21T18:21:14.236Z,1398104474.236 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-21T18:21:14.236Z,1398104474.236 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-21T18:21:14.236Z,1398104474.236 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T18:21:14.237Z,1398104474.237 [Default:Iridium:B.GoToSurface] Stopped
2014-04-21T18:21:14.237Z,1398104474.237 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-21T18:21:14.237Z,1398104474.237 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-21T18:21:14.238Z,1398104474.238 [Default:GPS] Running Loop=1
2014-04-21T18:21:14.238Z,1398104474.238 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-21T18:21:14.238Z,1398104474.238 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-21T18:21:14.238Z,1398104474.238 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-21T18:21:14.238Z,1398104474.238 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-21T18:21:14.238Z,1398104474.238 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T18:21:14.239Z,1398104474.239 [Default:GPS:B.GoToSurface] Stopped
2014-04-21T18:21:14.239Z,1398104474.239 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-21T18:21:14.239Z,1398104474.239 [Default:GPS:Read_GPS] Running Loop=1
2014-04-21T18:21:15.308Z,1398104475.308 [NAL9602](INFO): Powering up
2014-04-21T18:21:26.131Z,1398104486.131 [NAL9602](INFO): NAL9602 initialized
2014-04-21T18:21:53.530Z,1398104513.530 [NAL9602](INFO): SBD MO Status=1, MOMSN=28200, MT Status=0, MTMSN=0
2014-04-21T18:21:53.581Z,1398104513.581 [NAL9602](INFO): Sent 76 bytes from file Logs/20140421T175838/Courier0012.lzma
2014-04-21T18:21:53.582Z,1398104513.582 [NAL9602](INFO): Packets left to send: 0
2014-04-21T18:21:53.583Z,1398104513.583 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Courier0012.lzma.parts/0000.sbd
2014-04-21T18:21:53.583Z,1398104513.583 [NAL9602](INFO): Completed sending Logs/20140421T175838/Courier0012.lzma
2014-04-21T18:22:07.339Z,1398104527.339 [NAL9602](INFO): SBD MO Status=1, MOMSN=28201, MT Status=0, MTMSN=0
2014-04-21T18:22:07.399Z,1398104527.399 [NAL9602](INFO): Sent 332 bytes from file Logs/20140421T175838/Express0013.lzma
2014-04-21T18:22:07.399Z,1398104527.399 [NAL9602](INFO): Packets left to send: 1
2014-04-21T18:22:07.401Z,1398104527.401 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Express0013.lzma.parts/0001.sbd
2014-04-21T18:22:18.089Z,1398104538.089 [NAL9602](INFO): SBD MO Status=1, MOMSN=28202, MT Status=0, MTMSN=0
2014-04-21T18:22:18.152Z,1398104538.152 [NAL9602](INFO): Sent 34 bytes from file Logs/20140421T175838/Express0013.lzma
2014-04-21T18:22:18.152Z,1398104538.152 [NAL9602](INFO): Packets left to send: 0
2014-04-21T18:22:18.154Z,1398104538.154 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Express0013.lzma.parts/0000.sbd
2014-04-21T18:22:18.154Z,1398104538.154 [NAL9602](INFO): Completed sending Logs/20140421T175838/Express0013.lzma
2014-04-21T18:22:28.599Z,1398104548.599 [NAL9602](INFO): SBD MO Status=0, MOMSN=28203, MT Status=0, MTMSN=0
2014-04-21T18:22:28.686Z,1398104548.686 [Default:Iridium:Read_Iridium] Stopped
2014-04-21T18:22:28.687Z,1398104548.687 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-21T18:22:28.687Z,1398104548.687 [Default:Iridium] Stopped
2014-04-21T18:22:28.687Z,1398104548.687 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-21T18:22:28.687Z,1398104548.687 [Default:Iridium:A.SetSpeed] Stopped
2014-04-21T18:22:28.687Z,1398104548.687 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T18:22:29.092Z,1398104549.092 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-21T18:22:29.092Z,1398104549.092 [Default:CallIridium:B] Stopped
2014-04-21T18:22:29.092Z,1398104549.092 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-21T18:22:29.092Z,1398104549.092 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-21T18:22:29.093Z,1398104549.093 [Default:CallIridium] Stopped
2014-04-21T18:22:29.093Z,1398104549.093 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-21T18:22:29.937Z,1398104549.937 [NAL9602](IMPORTANT): GPS fix at: 1398104529.00
2014-04-21T18:22:29.955Z,1398104549.955 [DeadReckonUsingMultipleVelocitySources](DEBUG): horizontalPathLengthSinceLastFix_ = 1001.1, recording fix residuals...
2014-04-21T18:22:29.960Z,1398104549.960 [UniversalFixResidualReporter](DEBUG): Fix parameters were touched since the last run.
2014-04-21T18:22:29.960Z,1398104549.960 [UniversalFixResidualReporter](IMPORTANT): Fix residual: 4.6 %DT, over the last 747.2 m. Residual distance 46.3 m at bearing 11.8 degrees. Fix at (33.5898, -117.8789) with 747.2 m made good.
2014-04-21T18:22:29.962Z,1398104549.962 [Default:GPS:Read_GPS] Stopped
2014-04-21T18:22:29.962Z,1398104549.962 [Default:GPS:D] Running Loop=1
2014-04-21T18:22:30.465Z,1398104550.465 [Default:GPS:D] Stopped
2014-04-21T18:22:30.465Z,1398104550.465 [Default:GPS](INFO): Completed Default:GPS
2014-04-21T18:22:30.465Z,1398104550.465 [Default:GPS] Stopped
2014-04-21T18:22:30.465Z,1398104550.465 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-21T18:22:30.465Z,1398104550.465 [Default:GPS:A.SetSpeed] Stopped
2014-04-21T18:22:30.466Z,1398104550.466 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T18:22:51.009Z,1398104571.009 [NAL9602](INFO): Powering down
2014-04-21T18:27:31.072Z,1398104851.072 [Default:CallIridium] Running Loop=1
2014-04-21T18:27:31.072Z,1398104851.072 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-21T18:27:31.077Z,1398104851.077 [Default:CallIridium:A] Running Loop=1
2014-04-21T18:27:31.077Z,1398104851.077 [Default:CallIridium:A] Stopped
2014-04-21T18:27:31.077Z,1398104851.077 [Default:CallIridium:B] Running Loop=1
2014-04-21T18:27:31.080Z,1398104851.080 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-21T18:27:36.042Z,1398104856.042 [Default:Iridium] Running Loop=1
2014-04-21T18:27:36.042Z,1398104856.042 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-21T18:27:36.042Z,1398104856.042 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-21T18:27:36.042Z,1398104856.042 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-21T18:27:36.042Z,1398104856.042 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-21T18:27:36.042Z,1398104856.042 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T18:27:36.043Z,1398104856.043 [Default:Iridium:B.GoToSurface] Stopped
2014-04-21T18:27:36.043Z,1398104856.043 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-21T18:27:36.043Z,1398104856.043 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-21T18:27:36.043Z,1398104856.043 [Default:GPS] Running Loop=1
2014-04-21T18:27:36.044Z,1398104856.044 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-21T18:27:36.048Z,1398104856.048 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-21T18:27:36.048Z,1398104856.048 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-21T18:27:36.048Z,1398104856.048 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-21T18:27:36.048Z,1398104856.048 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T18:27:36.049Z,1398104856.049 [Default:GPS:B.GoToSurface] Stopped
2014-04-21T18:27:36.049Z,1398104856.049 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-21T18:27:36.049Z,1398104856.049 [Default:GPS:Read_GPS] Running Loop=1
2014-04-21T18:27:37.172Z,1398104857.172 [NAL9602](INFO): Powering up
2014-04-21T18:27:47.995Z,1398104867.995 [NAL9602](INFO): NAL9602 initialized
2014-04-21T18:28:27.644Z,1398104907.644 [NAL9602](INFO): SBD MO Status=2, MOMSN=28204, MT Status=2, MTMSN=0
2014-04-21T18:28:27.644Z,1398104907.644 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T18:28:29.008Z,1398104909.008 [NAL9602](IMPORTANT): GPS fix at: 1398104888.00
2014-04-21T18:28:29.041Z,1398104909.041 [DeadReckonUsingMultipleVelocitySources](DEBUG): horizontalPathLengthSinceLastFix_ = 698.824, recording fix residuals...
2014-04-21T18:28:29.050Z,1398104909.050 [UniversalFixResidualReporter](DEBUG): Fix parameters were touched since the last run.
2014-04-21T18:28:29.059Z,1398104909.059 [UniversalFixResidualReporter](IMPORTANT): Fix residual: 7.6 %DT, over the last 745.2 m. Residual distance 53.0 m at bearing 164.9 degrees. Fix at (33.5964, -117.8800) with 745.2 m made good.
2014-04-21T18:28:29.061Z,1398104909.061 [Default:GPS:Read_GPS] Stopped
2014-04-21T18:28:29.061Z,1398104909.061 [Default:GPS:D] Running Loop=1
2014-04-21T18:28:29.478Z,1398104909.478 [Default:GPS:D] Stopped
2014-04-21T18:28:29.495Z,1398104909.495 [Default:GPS](INFO): Completed Default:GPS
2014-04-21T18:28:29.495Z,1398104909.495 [Default:GPS] Stopped
2014-04-21T18:28:29.495Z,1398104909.495 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-21T18:28:29.495Z,1398104909.495 [Default:GPS:A.SetSpeed] Stopped
2014-04-21T18:28:29.496Z,1398104909.496 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T18:28:57.889Z,1398104937.889 [NAL9602](INFO): SBD MO Status=2, MOMSN=28204, MT Status=2, MTMSN=0
2014-04-21T18:28:57.889Z,1398104937.889 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T18:29:18.904Z,1398104958.904 [NAL9602](INFO): SBD MO Status=2, MOMSN=28204, MT Status=2, MTMSN=0
2014-04-21T18:29:18.905Z,1398104958.905 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T18:29:19.836Z,1398104959.836 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#6 STATUS: 65535
2014-04-21T18:30:05.079Z,1398105005.079 [NAL9602](INFO): SBD MO Status=2, MOMSN=28204, MT Status=2, MTMSN=0
2014-04-21T18:30:05.080Z,1398105005.080 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T18:30:31.187Z,1398105031.187 [NAL9602](INFO): SBD MO Status=2, MOMSN=28204, MT Status=2, MTMSN=0
2014-04-21T18:30:31.187Z,1398105031.187 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T18:30:56.952Z,1398105056.952 [NAL9602](INFO): SBD MO Status=2, MOMSN=28204, MT Status=2, MTMSN=0
2014-04-21T18:30:56.952Z,1398105056.952 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T18:31:31.766Z,1398105091.766 [NAL9602](INFO): SBD MO Status=2, MOMSN=28204, MT Status=2, MTMSN=0
2014-04-21T18:31:31.766Z,1398105091.766 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T18:31:54.848Z,1398105114.848 [NAL9602](INFO): SBD MO Status=2, MOMSN=28204, MT Status=2, MTMSN=0
2014-04-21T18:31:54.848Z,1398105114.848 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T18:32:11.516Z,1398105131.516 [NAL9602](INFO): SBD MO Status=1, MOMSN=28204, MT Status=0, MTMSN=0
2014-04-21T18:32:11.564Z,1398105131.564 [NAL9602](INFO): Sent 76 bytes from file Logs/20140421T175838/Courier0016.lzma
2014-04-21T18:32:11.564Z,1398105131.564 [NAL9602](INFO): Packets left to send: 0
2014-04-21T18:32:11.566Z,1398105131.566 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Courier0016.lzma.parts/0000.sbd
2014-04-21T18:32:11.566Z,1398105131.566 [NAL9602](INFO): Completed sending Logs/20140421T175838/Courier0016.lzma
2014-04-21T18:32:24.072Z,1398105144.072 [NAL9602](INFO): SBD MO Status=1, MOMSN=28205, MT Status=0, MTMSN=0
2014-04-21T18:32:24.127Z,1398105144.127 [NAL9602](INFO): Sent 231 bytes from file Logs/20140421T175838/Express0017.lzma
2014-04-21T18:32:24.127Z,1398105144.127 [NAL9602](INFO): Packets left to send: 0
2014-04-21T18:32:24.129Z,1398105144.129 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Express0017.lzma.parts/0000.sbd
2014-04-21T18:32:24.129Z,1398105144.129 [NAL9602](INFO): Completed sending Logs/20140421T175838/Express0017.lzma
2014-04-21T18:32:36.424Z,1398105156.424 [NAL9602](INFO): SBD MO Status=0, MOMSN=28206, MT Status=0, MTMSN=0
2014-04-21T18:32:36.518Z,1398105156.518 [Default:Iridium:Read_Iridium] Stopped
2014-04-21T18:32:36.518Z,1398105156.518 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-21T18:32:36.519Z,1398105156.519 [Default:Iridium] Stopped
2014-04-21T18:32:36.519Z,1398105156.519 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-21T18:32:36.519Z,1398105156.519 [Default:Iridium:A.SetSpeed] Stopped
2014-04-21T18:32:36.519Z,1398105156.519 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T18:32:36.890Z,1398105156.890 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-21T18:32:36.890Z,1398105156.890 [Default:CallIridium:B] Stopped
2014-04-21T18:32:36.890Z,1398105156.890 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-21T18:32:36.890Z,1398105156.890 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-21T18:32:36.890Z,1398105156.890 [Default:CallIridium] Stopped
2014-04-21T18:32:36.890Z,1398105156.890 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-21T18:32:47.066Z,1398105167.066 [NAL9602](INFO): Powering down
2014-04-21T18:37:37.067Z,1398105457.067 [Default:CallIridium] Running Loop=1
2014-04-21T18:37:37.067Z,1398105457.067 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-21T18:37:37.068Z,1398105457.068 [Default:CallIridium:A] Running Loop=1
2014-04-21T18:37:37.068Z,1398105457.068 [Default:CallIridium:A] Stopped
2014-04-21T18:37:37.068Z,1398105457.068 [Default:CallIridium:B] Running Loop=1
2014-04-21T18:37:37.068Z,1398105457.068 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-21T18:37:42.079Z,1398105462.079 [Default:Iridium] Running Loop=1
2014-04-21T18:37:42.079Z,1398105462.079 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-21T18:37:42.080Z,1398105462.080 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-21T18:37:42.080Z,1398105462.080 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-21T18:37:42.080Z,1398105462.080 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-21T18:37:42.080Z,1398105462.080 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T18:37:42.081Z,1398105462.081 [Default:Iridium:B.GoToSurface] Stopped
2014-04-21T18:37:42.081Z,1398105462.081 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-21T18:37:42.081Z,1398105462.081 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-21T18:37:42.081Z,1398105462.081 [Default:GPS] Running Loop=1
2014-04-21T18:37:42.081Z,1398105462.081 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-21T18:37:42.081Z,1398105462.081 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-21T18:37:42.082Z,1398105462.082 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-21T18:37:42.082Z,1398105462.082 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-21T18:37:42.082Z,1398105462.082 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T18:37:42.083Z,1398105462.083 [Default:GPS:B.GoToSurface] Stopped
2014-04-21T18:37:42.083Z,1398105462.083 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-21T18:37:42.083Z,1398105462.083 [Default:GPS:Read_GPS] Running Loop=1
2014-04-21T18:37:43.125Z,1398105463.125 [NAL9602](INFO): Powering up
2014-04-21T18:37:54.203Z,1398105474.203 [NAL9602](INFO): NAL9602 initialized
2014-04-21T18:38:29.130Z,1398105509.130 [NAL9602](INFO): SBD MO Status=2, MOMSN=28207, MT Status=2, MTMSN=0
2014-04-21T18:38:29.130Z,1398105509.130 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T18:38:54.652Z,1398105534.652 [NAL9602](INFO): SBD MO Status=2, MOMSN=28207, MT Status=2, MTMSN=0
2014-04-21T18:38:54.653Z,1398105534.653 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T18:38:56.046Z,1398105536.046 [NAL9602](IMPORTANT): GPS fix at: 1398105515.00
2014-04-21T18:38:56.062Z,1398105536.062 [DeadReckonUsingMultipleVelocitySources](DEBUG): horizontalPathLengthSinceLastFix_ = 1187.7, recording fix residuals...
2014-04-21T18:38:56.066Z,1398105536.066 [UniversalFixResidualReporter](DEBUG): Fix parameters were touched since the last run.
2014-04-21T18:38:56.067Z,1398105536.067 [UniversalFixResidualReporter](IMPORTANT): Fix residual: 8.8 %DT, over the last 1206.3 m. Residual distance 103.9 m at bearing 105.2 degrees. Fix at (33.6022, -117.8910) with 1206.3 m made good.
2014-04-21T18:38:56.069Z,1398105536.069 [Default:GPS:Read_GPS] Stopped
2014-04-21T18:38:56.070Z,1398105536.070 [Default:GPS:D] Running Loop=1
2014-04-21T18:38:56.551Z,1398105536.551 [Default:GPS:D] Stopped
2014-04-21T18:38:56.555Z,1398105536.555 [Default:GPS](INFO): Completed Default:GPS
2014-04-21T18:38:56.555Z,1398105536.555 [Default:GPS] Stopped
2014-04-21T18:38:56.555Z,1398105536.555 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-21T18:38:56.555Z,1398105536.555 [Default:GPS:A.SetSpeed] Stopped
2014-04-21T18:38:56.555Z,1398105536.555 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T18:39:15.069Z,1398105555.069 [NAL9602](INFO): SBD MO Status=1, MOMSN=28207, MT Status=0, MTMSN=0
2014-04-21T18:39:15.124Z,1398105555.124 [NAL9602](INFO): Sent 76 bytes from file Logs/20140421T175838/Courier0020.lzma
2014-04-21T18:39:15.124Z,1398105555.124 [NAL9602](INFO): Packets left to send: 0
2014-04-21T18:39:15.127Z,1398105555.127 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Courier0020.lzma.parts/0000.sbd
2014-04-21T18:39:15.134Z,1398105555.134 [NAL9602](INFO): Completed sending Logs/20140421T175838/Courier0020.lzma
2014-04-21T18:39:33.635Z,1398105573.635 [NAL9602](INFO): SBD MO Status=1, MOMSN=28208, MT Status=0, MTMSN=0
2014-04-21T18:39:33.685Z,1398105573.685 [NAL9602](INFO): Sent 264 bytes from file Logs/20140421T175838/Express0021.lzma
2014-04-21T18:39:33.686Z,1398105573.686 [NAL9602](INFO): Packets left to send: 0
2014-04-21T18:39:33.687Z,1398105573.687 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Express0021.lzma.parts/0000.sbd
2014-04-21T18:39:33.687Z,1398105573.687 [NAL9602](INFO): Completed sending Logs/20140421T175838/Express0021.lzma
2014-04-21T18:39:45.029Z,1398105585.029 [NAL9602](INFO): SBD MO Status=0, MOMSN=28209, MT Status=0, MTMSN=0
2014-04-21T18:39:45.118Z,1398105585.118 [Default:Iridium:Read_Iridium] Stopped
2014-04-21T18:39:45.118Z,1398105585.118 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-21T18:39:45.119Z,1398105585.119 [Default:Iridium] Stopped
2014-04-21T18:39:45.119Z,1398105585.119 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-21T18:39:45.119Z,1398105585.119 [Default:Iridium:A.SetSpeed] Stopped
2014-04-21T18:39:45.119Z,1398105585.119 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T18:39:45.523Z,1398105585.523 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-21T18:39:45.523Z,1398105585.523 [Default:CallIridium:B] Stopped
2014-04-21T18:39:45.523Z,1398105585.523 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-21T18:39:45.523Z,1398105585.523 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-21T18:39:45.524Z,1398105585.524 [Default:CallIridium] Stopped
2014-04-21T18:39:45.524Z,1398105585.524 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-21T18:39:55.630Z,1398105595.630 [NAL9602](INFO): Powering down
2014-04-21T18:44:45.681Z,1398105885.681 [Default:CallIridium] Running Loop=1
2014-04-21T18:44:45.681Z,1398105885.681 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-21T18:44:45.682Z,1398105885.682 [Default:CallIridium:A] Running Loop=1
2014-04-21T18:44:45.682Z,1398105885.682 [Default:CallIridium:A] Stopped
2014-04-21T18:44:45.682Z,1398105885.682 [Default:CallIridium:B] Running Loop=1
2014-04-21T18:44:45.682Z,1398105885.682 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-21T18:44:50.693Z,1398105890.693 [Default:Iridium] Running Loop=1
2014-04-21T18:44:50.693Z,1398105890.693 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-21T18:44:50.693Z,1398105890.693 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-21T18:44:50.693Z,1398105890.693 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-21T18:44:50.693Z,1398105890.693 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-21T18:44:50.693Z,1398105890.693 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T18:44:50.694Z,1398105890.694 [Default:Iridium:B.GoToSurface] Stopped
2014-04-21T18:44:50.694Z,1398105890.694 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-21T18:44:50.694Z,1398105890.694 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-21T18:44:50.695Z,1398105890.695 [Default:GPS] Running Loop=1
2014-04-21T18:44:50.695Z,1398105890.695 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-21T18:44:50.695Z,1398105890.695 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-21T18:44:50.695Z,1398105890.695 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-21T18:44:50.695Z,1398105890.695 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-21T18:44:50.695Z,1398105890.695 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T18:44:50.716Z,1398105890.716 [Default:GPS:B.GoToSurface] Stopped
2014-04-21T18:44:50.716Z,1398105890.716 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-21T18:44:50.716Z,1398105890.716 [Default:GPS:Read_GPS] Running Loop=1
2014-04-21T18:44:51.776Z,1398105891.776 [NAL9602](INFO): Powering up
2014-04-21T18:45:02.651Z,1398105902.651 [NAL9602](INFO): NAL9602 initialized
2014-04-21T18:45:27.295Z,1398105927.295 [NAL9602](INFO): SBD MO Status=2, MOMSN=28210, MT Status=2, MTMSN=0
2014-04-21T18:45:27.295Z,1398105927.295 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T18:45:28.577Z,1398105928.577 [NAL9602](IMPORTANT): GPS fix at: 1398105907.00
2014-04-21T18:45:28.593Z,1398105928.593 [DeadReckonUsingMultipleVelocitySources](DEBUG): horizontalPathLengthSinceLastFix_ = 704.769, recording fix residuals...
2014-04-21T18:45:28.597Z,1398105928.597 [UniversalFixResidualReporter](DEBUG): Fix parameters were touched since the last run.
2014-04-21T18:45:28.598Z,1398105928.598 [UniversalFixResidualReporter](IMPORTANT): Fix residual: 12.6 %DT, over the last 777.6 m. Residual distance 88.7 m at bearing 94.2 degrees. Fix at (33.6047, -117.8988) with 777.6 m made good.
2014-04-21T18:45:28.600Z,1398105928.600 [Default:GPS:Read_GPS] Stopped
2014-04-21T18:45:28.600Z,1398105928.600 [Default:GPS:D] Running Loop=1
2014-04-21T18:45:29.066Z,1398105929.066 [Default:GPS:D] Stopped
2014-04-21T18:45:29.067Z,1398105929.067 [Default:GPS](INFO): Completed Default:GPS
2014-04-21T18:45:29.067Z,1398105929.067 [Default:GPS] Stopped
2014-04-21T18:45:29.067Z,1398105929.067 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-21T18:45:29.067Z,1398105929.067 [Default:GPS:A.SetSpeed] Stopped
2014-04-21T18:45:29.067Z,1398105929.067 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T18:45:51.533Z,1398105951.533 [NAL9602](INFO): SBD MO Status=1, MOMSN=28210, MT Status=0, MTMSN=0
2014-04-21T18:45:51.587Z,1398105951.587 [NAL9602](INFO): Sent 76 bytes from file Logs/20140421T175838/Courier0024.lzma
2014-04-21T18:45:51.587Z,1398105951.587 [NAL9602](INFO): Packets left to send: 0
2014-04-21T18:45:51.590Z,1398105951.590 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Courier0024.lzma.parts/0000.sbd
2014-04-21T18:45:51.590Z,1398105951.590 [NAL9602](INFO): Completed sending Logs/20140421T175838/Courier0024.lzma
2014-04-21T18:46:06.454Z,1398105966.454 [NAL9602](INFO): SBD MO Status=2, MOMSN=28211, MT Status=2, MTMSN=0
2014-04-21T18:46:06.454Z,1398105966.454 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T18:46:27.911Z,1398105987.911 [NAL9602](INFO): SBD MO Status=1, MOMSN=28211, MT Status=0, MTMSN=0
2014-04-21T18:46:27.960Z,1398105987.960 [NAL9602](INFO): Sent 264 bytes from file Logs/20140421T175838/Express0025.lzma
2014-04-21T18:46:27.960Z,1398105987.960 [NAL9602](INFO): Packets left to send: 0
2014-04-21T18:46:27.961Z,1398105987.961 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Express0025.lzma.parts/0000.sbd
2014-04-21T18:46:27.962Z,1398105987.962 [NAL9602](INFO): Completed sending Logs/20140421T175838/Express0025.lzma
2014-04-21T18:46:31.535Z,1398105991.535 [NAL9602](INFO): SBD MO Status=0, MOMSN=28212, MT Status=0, MTMSN=0
2014-04-21T18:46:31.624Z,1398105991.624 [Default:Iridium:Read_Iridium] Stopped
2014-04-21T18:46:31.624Z,1398105991.624 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-21T18:46:31.625Z,1398105991.625 [Default:Iridium] Stopped
2014-04-21T18:46:31.625Z,1398105991.625 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-21T18:46:31.625Z,1398105991.625 [Default:Iridium:A.SetSpeed] Stopped
2014-04-21T18:46:31.625Z,1398105991.625 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T18:46:32.034Z,1398105992.034 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-21T18:46:32.034Z,1398105992.034 [Default:CallIridium:B] Stopped
2014-04-21T18:46:32.034Z,1398105992.034 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-21T18:46:32.034Z,1398105992.034 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-21T18:46:32.034Z,1398105992.034 [Default:CallIridium] Stopped
2014-04-21T18:46:32.034Z,1398105992.034 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-21T18:46:42.127Z,1398106002.127 [NAL9602](INFO): Powering down
2014-04-21T18:51:32.195Z,1398106292.195 [Default:CallIridium] Running Loop=1
2014-04-21T18:51:32.195Z,1398106292.195 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-21T18:51:32.196Z,1398106292.196 [Default:CallIridium:A] Running Loop=1
2014-04-21T18:51:32.196Z,1398106292.196 [Default:CallIridium:A] Stopped
2014-04-21T18:51:32.196Z,1398106292.196 [Default:CallIridium:B] Running Loop=1
2014-04-21T18:51:32.196Z,1398106292.196 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-21T18:51:37.214Z,1398106297.214 [Default:Iridium] Running Loop=1
2014-04-21T18:51:37.214Z,1398106297.214 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-21T18:51:37.214Z,1398106297.214 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-21T18:51:37.214Z,1398106297.214 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-21T18:51:37.223Z,1398106297.223 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-21T18:51:37.223Z,1398106297.223 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T18:51:37.223Z,1398106297.223 [Default:Iridium:B.GoToSurface] Stopped
2014-04-21T18:51:37.224Z,1398106297.224 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-21T18:51:37.224Z,1398106297.224 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-21T18:51:37.224Z,1398106297.224 [Default:GPS] Running Loop=1
2014-04-21T18:51:37.224Z,1398106297.224 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-21T18:51:37.224Z,1398106297.224 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-21T18:51:37.224Z,1398106297.224 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-21T18:51:37.224Z,1398106297.224 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-21T18:51:37.225Z,1398106297.225 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T18:51:37.225Z,1398106297.225 [Default:GPS:B.GoToSurface] Stopped
2014-04-21T18:51:37.225Z,1398106297.225 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-21T18:51:37.226Z,1398106297.226 [Default:GPS:Read_GPS] Running Loop=1
2014-04-21T18:51:38.299Z,1398106298.299 [NAL9602](INFO): Powering up
2014-04-21T18:51:49.241Z,1398106309.241 [NAL9602](INFO): NAL9602 initialized
2014-04-21T18:52:18.041Z,1398106338.041 [NAL9602](IMPORTANT): GPS fix at: 1398106317.00
2014-04-21T18:52:18.056Z,1398106338.056 [DeadReckonUsingMultipleVelocitySources](DEBUG): horizontalPathLengthSinceLastFix_ = 813.993, recording fix residuals...
2014-04-21T18:52:18.076Z,1398106338.076 [UniversalFixResidualReporter](DEBUG): Fix parameters were touched since the last run.
2014-04-21T18:52:18.077Z,1398106338.077 [UniversalFixResidualReporter](IMPORTANT): Fix residual: 5.0 %DT, over the last 840.9 m. Residual distance 40.7 m at bearing 96.5 degrees. Fix at (33.6096, -117.9058) with 840.9 m made good.
2014-04-21T18:52:18.087Z,1398106338.087 [Default:GPS:Read_GPS] Stopped
2014-04-21T18:52:18.088Z,1398106338.088 [Default:GPS:D] Running Loop=1
2014-04-21T18:52:18.501Z,1398106338.501 [Default:GPS:D] Stopped
2014-04-21T18:52:18.501Z,1398106338.501 [Default:GPS](INFO): Completed Default:GPS
2014-04-21T18:52:18.501Z,1398106338.501 [Default:GPS] Stopped
2014-04-21T18:52:18.501Z,1398106338.501 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-21T18:52:18.501Z,1398106338.501 [Default:GPS:A.SetSpeed] Stopped
2014-04-21T18:52:18.501Z,1398106338.501 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T18:53:53.286Z,1398106433.286 [NAL9602](INFO): SBD MO Status=2, MOMSN=28213, MT Status=2, MTMSN=0
2014-04-21T18:53:53.286Z,1398106433.286 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T18:54:53.385Z,1398106493.385 [NAL9602](INFO): SBD MO Status=2, MOMSN=28213, MT Status=2, MTMSN=0
2014-04-21T18:54:53.386Z,1398106493.386 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T18:55:15.128Z,1398106515.128 [NAL9602](INFO): SBD MO Status=2, MOMSN=28213, MT Status=2, MTMSN=0
2014-04-21T18:55:15.129Z,1398106515.129 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T18:55:47.039Z,1398106547.039 [NAL9602](INFO): SBD MO Status=1, MOMSN=28213, MT Status=0, MTMSN=0
2014-04-21T18:55:47.090Z,1398106547.090 [NAL9602](INFO): Sent 76 bytes from file Logs/20140421T175838/Courier0028.lzma
2014-04-21T18:55:47.090Z,1398106547.090 [NAL9602](INFO): Packets left to send: 0
2014-04-21T18:55:47.092Z,1398106547.092 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Courier0028.lzma.parts/0000.sbd
2014-04-21T18:55:47.092Z,1398106547.092 [NAL9602](INFO): Completed sending Logs/20140421T175838/Courier0028.lzma
2014-04-21T18:56:04.521Z,1398106564.521 [NAL9602](INFO): SBD MO Status=1, MOMSN=28214, MT Status=0, MTMSN=0
2014-04-21T18:56:04.570Z,1398106564.570 [NAL9602](INFO): Sent 254 bytes from file Logs/20140421T175838/Express0029.lzma
2014-04-21T18:56:04.570Z,1398106564.570 [NAL9602](INFO): Packets left to send: 0
2014-04-21T18:56:04.571Z,1398106564.571 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Express0029.lzma.parts/0000.sbd
2014-04-21T18:56:04.572Z,1398106564.572 [NAL9602](INFO): Completed sending Logs/20140421T175838/Express0029.lzma
2014-04-21T18:56:13.367Z,1398106573.367 [NAL9602](INFO): SBD MO Status=0, MOMSN=28215, MT Status=0, MTMSN=0
2014-04-21T18:56:13.458Z,1398106573.458 [Default:Iridium:Read_Iridium] Stopped
2014-04-21T18:56:13.459Z,1398106573.459 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-21T18:56:13.459Z,1398106573.459 [Default:Iridium] Stopped
2014-04-21T18:56:13.459Z,1398106573.459 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-21T18:56:13.459Z,1398106573.459 [Default:Iridium:A.SetSpeed] Stopped
2014-04-21T18:56:13.459Z,1398106573.459 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T18:56:13.905Z,1398106573.905 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-21T18:56:13.905Z,1398106573.905 [Default:CallIridium:B] Stopped
2014-04-21T18:56:13.905Z,1398106573.905 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-21T18:56:13.905Z,1398106573.905 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-21T18:56:13.905Z,1398106573.905 [Default:CallIridium] Stopped
2014-04-21T18:56:13.905Z,1398106573.905 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-21T18:56:19.013Z,1398106579.013 [Depth_Keller](ERROR): Pressure reading out of range: 1830.946411 decibar
2014-04-21T18:56:24.003Z,1398106584.003 [NAL9602](INFO): Powering down
2014-04-21T18:56:54.040Z,1398106614.040 [Depth_Keller](ERROR): Pressure reading out of range: 1830.936768 decibar
2014-04-21T18:57:54.012Z,1398106674.012 [Depth_Keller](ERROR): Pressure reading out of range: 1830.961304 decibar
2014-04-21T18:57:54.083Z,1398106674.083 [Radio_Freewave](INFO): Powering down
2014-04-21T18:58:04.067Z,1398106684.067 [Radio_Freewave](INFO): Powering up
2014-04-21T18:58:08.996Z,1398106688.996 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0
2014-04-21T18:59:13.992Z,1398106753.992 [Depth_Keller](ERROR): Pressure reading out of range: 1830.917603 decibar
2014-04-21T18:59:14.067Z,1398106754.067 [Radio_Freewave](INFO): Powering down
2014-04-21T18:59:24.019Z,1398106764.019 [Radio_Freewave](INFO): Powering up
2014-04-21T18:59:29.014Z,1398106769.014 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0
2014-04-21T19:00:38.995Z,1398106838.995 [Depth_Keller](ERROR): Pressure reading out of range: 1830.891479 decibar
2014-04-21T19:00:39.052Z,1398106839.052 [Radio_Freewave](INFO): Powering down
2014-04-21T19:00:49.029Z,1398106849.029 [Radio_Freewave](INFO): Powering up
2014-04-21T19:00:53.994Z,1398106853.994 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0
2014-04-21T19:01:03.976Z,1398106863.976 [Depth_Keller](ERROR): Pressure reading out of range: 1830.956909 decibar
2014-04-21T19:01:04.018Z,1398106864.018 [Radio_Freewave](INFO): Powering down
2014-04-21T19:01:14.021Z,1398106874.021 [Radio_Freewave](INFO): Powering up
2014-04-21T19:01:14.086Z,1398106874.086 [Default:CallIridium] Running Loop=1
2014-04-21T19:01:14.086Z,1398106874.086 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-21T19:01:14.086Z,1398106874.086 [Default:CallIridium:A] Running Loop=1
2014-04-21T19:01:14.087Z,1398106874.087 [Default:CallIridium:A] Stopped
2014-04-21T19:01:14.087Z,1398106874.087 [Default:CallIridium:B] Running Loop=1
2014-04-21T19:01:14.087Z,1398106874.087 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-21T19:01:19.021Z,1398106879.021 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0
2014-04-21T19:01:19.094Z,1398106879.094 [Default:Iridium] Running Loop=1
2014-04-21T19:01:19.094Z,1398106879.094 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-21T19:01:19.094Z,1398106879.094 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-21T19:01:19.095Z,1398106879.095 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-21T19:01:19.095Z,1398106879.095 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-21T19:01:19.095Z,1398106879.095 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T19:01:19.096Z,1398106879.096 [Default:Iridium:B.GoToSurface] Stopped
2014-04-21T19:01:19.096Z,1398106879.096 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-21T19:01:19.096Z,1398106879.096 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-21T19:01:19.097Z,1398106879.097 [Default:GPS] Running Loop=1
2014-04-21T19:01:19.097Z,1398106879.097 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-21T19:01:19.097Z,1398106879.097 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-21T19:01:19.097Z,1398106879.097 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-21T19:01:19.097Z,1398106879.097 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-21T19:01:19.097Z,1398106879.097 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T19:01:19.098Z,1398106879.098 [Default:GPS:B.GoToSurface] Stopped
2014-04-21T19:01:19.098Z,1398106879.098 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-21T19:01:19.098Z,1398106879.098 [Default:GPS:Read_GPS] Running Loop=1
2014-04-21T19:01:20.229Z,1398106880.229 [NAL9602](INFO): Powering up
2014-04-21T19:01:31.348Z,1398106891.348 [NAL9602](INFO): NAL9602 initialized
2014-04-21T19:01:59.375Z,1398106919.375 [NAL9602](INFO): SBD MO Status=2, MOMSN=28216, MT Status=2, MTMSN=0
2014-04-21T19:01:59.376Z,1398106919.376 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T19:02:00.663Z,1398106920.663 [NAL9602](IMPORTANT): GPS fix at: 1398106899.00
2014-04-21T19:02:00.677Z,1398106920.677 [DeadReckonUsingMultipleVelocitySources](DEBUG): horizontalPathLengthSinceLastFix_ = 1037.72, recording fix residuals...
2014-04-21T19:02:00.681Z,1398106920.681 [UniversalFixResidualReporter](DEBUG): Fix parameters were touched since the last run.
2014-04-21T19:02:00.682Z,1398106920.682 [UniversalFixResidualReporter](IMPORTANT): Fix residual: 11.9 %DT, over the last 1151.4 m. Residual distance 123.6 m at bearing 105.4 degrees. Fix at (33.6150, -117.9164) with 1151.4 m made good.
2014-04-21T19:02:00.684Z,1398106920.684 [Default:GPS:Read_GPS] Stopped
2014-04-21T19:02:00.685Z,1398106920.685 [Default:GPS:D] Running Loop=1
2014-04-21T19:02:01.198Z,1398106921.198 [Default:GPS:D] Stopped
2014-04-21T19:02:01.198Z,1398106921.198 [Default:GPS](INFO): Completed Default:GPS
2014-04-21T19:02:01.198Z,1398106921.198 [Default:GPS] Stopped
2014-04-21T19:02:01.199Z,1398106921.199 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-21T19:02:01.199Z,1398106921.199 [Default:GPS:A.SetSpeed] Stopped
2014-04-21T19:02:01.199Z,1398106921.199 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T19:02:26.131Z,1398106946.131 [NAL9602](INFO): SBD MO Status=2, MOMSN=28216, MT Status=2, MTMSN=0
2014-04-21T19:02:26.131Z,1398106946.131 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T19:03:07.556Z,1398106987.556 [NAL9602](INFO): SBD MO Status=1, MOMSN=28216, MT Status=0, MTMSN=0
2014-04-21T19:03:07.618Z,1398106987.618 [NAL9602](INFO): Sent 76 bytes from file Logs/20140421T175838/Courier0032.lzma
2014-04-21T19:03:07.619Z,1398106987.619 [NAL9602](INFO): Packets left to send: 0
2014-04-21T19:03:07.620Z,1398106987.620 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Courier0032.lzma.parts/0000.sbd
2014-04-21T19:03:07.620Z,1398106987.620 [NAL9602](INFO): Completed sending Logs/20140421T175838/Courier0032.lzma
2014-04-21T19:03:24.653Z,1398107004.653 [NAL9602](INFO): SBD MO Status=1, MOMSN=28217, MT Status=0, MTMSN=0
2014-04-21T19:03:24.708Z,1398107004.708 [NAL9602](INFO): Sent 332 bytes from file Logs/20140421T175838/Express0033.lzma
2014-04-21T19:03:24.708Z,1398107004.708 [NAL9602](INFO): Packets left to send: 1
2014-04-21T19:03:24.711Z,1398107004.711 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Express0033.lzma.parts/0001.sbd
2014-04-21T19:03:39.506Z,1398107019.506 [NAL9602](INFO): SBD MO Status=2, MOMSN=28218, MT Status=2, MTMSN=0
2014-04-21T19:03:39.519Z,1398107019.519 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T19:03:50.968Z,1398107030.968 [NAL9602](INFO): SBD MO Status=1, MOMSN=28218, MT Status=0, MTMSN=0
2014-04-21T19:03:51.013Z,1398107031.013 [NAL9602](INFO): Sent 93 bytes from file Logs/20140421T175838/Express0033.lzma
2014-04-21T19:03:51.013Z,1398107031.013 [NAL9602](INFO): Packets left to send: 0
2014-04-21T19:03:51.014Z,1398107031.014 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Express0033.lzma.parts/0000.sbd
2014-04-21T19:03:51.014Z,1398107031.014 [NAL9602](INFO): Completed sending Logs/20140421T175838/Express0033.lzma
2014-04-21T19:03:59.455Z,1398107039.455 [NAL9602](INFO): SBD MO Status=0, MOMSN=28219, MT Status=0, MTMSN=0
2014-04-21T19:03:59.538Z,1398107039.538 [Default:Iridium:Read_Iridium] Stopped
2014-04-21T19:03:59.539Z,1398107039.539 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-21T19:03:59.539Z,1398107039.539 [Default:Iridium] Stopped
2014-04-21T19:03:59.539Z,1398107039.539 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-21T19:03:59.539Z,1398107039.539 [Default:Iridium:A.SetSpeed] Stopped
2014-04-21T19:03:59.539Z,1398107039.539 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T19:03:59.922Z,1398107039.922 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-21T19:03:59.938Z,1398107039.938 [Default:CallIridium:B] Stopped
2014-04-21T19:03:59.938Z,1398107039.938 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-21T19:03:59.938Z,1398107039.938 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-21T19:03:59.938Z,1398107039.938 [Default:CallIridium] Stopped
2014-04-21T19:03:59.939Z,1398107039.939 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-21T19:04:10.087Z,1398107050.087 [NAL9602](INFO): Powering down
2014-04-21T19:06:55.133Z,1398107215.133 [Depth_Keller](ERROR): Pressure reading out of range: 1830.826782 decibar
2014-04-21T19:06:55.174Z,1398107215.174 [Radio_Freewave](INFO): Powering down
2014-04-21T19:07:05.133Z,1398107225.133 [Radio_Freewave](INFO): Powering up
2014-04-21T19:07:10.052Z,1398107230.052 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0