2019-07-08T22:17:30.636Z,1562624250.636 [CommandLine](IMPORTANT): got command restart logs 2019-07-08T22:17:31.652Z,1562624251.652 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-08T22:17:31.652Z,1562624251.652 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-07-08T22:17:36.507Z,1562624256.507 [Default:A.Wait](INFO): Done Waiting. 2019-07-08T22:17:36.507Z,1562624256.507 [Default:A.Wait] Stopped 2019-07-08T22:17:36.507Z,1562624256.507 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2019-07-08T22:17:36.944Z,1562624256.944 [Default:CheckIn] Running Loop=1 2019-07-08T22:17:36.945Z,1562624256.945 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-08T22:17:36.945Z,1562624256.945 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-08T22:17:38.519Z,1562624258.519 [NAL9602](DEBUG): Fix Requested 2019-07-08T22:17:38.935Z,1562624258.935 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,221726.00,A,3648.14005,N,12147.20695,W,0.117,50.42,080719,,,D*48 2019-07-08T22:17:38.949Z,1562624258.949 [NAL9602](INFO): GPS fix at 20190708T221726: (36.802334, -121.786783) 2019-07-08T22:17:38.989Z,1562624258.989 [Default:CheckIn:Read_GPS] Stopped 2019-07-08T22:17:38.989Z,1562624258.989 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-08T22:17:39.741Z,1562624259.741 [Micromodem](ERROR): Buffer fill timout failure. 2019-07-08T22:17:41.444Z,1562624261.444 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 20BF235D000001005D00000400540100000000000000151D80030C5669BF3148E2FA22188B6A3173E5573572661C0BCBDFFAB423BD32D9A51E8904B0A920CE9A 2019-07-08T22:17:41.444Z,1562624261.444 [Micromodem](INFO): Outgoing frame #2, 64 bytes: EF9F66414C9B9FD6761AD008C3E3DC4FCA2E4E25B6359B14B772C256504760B95108769F133EF900356E4A82FC7917069709FEF9BCD9C9E1D0AD78DEFCA2E5CB 2019-07-08T22:17:41.445Z,1562624261.445 [Micromodem](INFO): Outgoing frame #3, 64 bytes: 98CF72178E3B15D1468D1FDCB70B169565E1DDE4A2530F9435651DD9D56B635A84B0C315798D20A429BAC52CD122DD0CBBE78055BA2DBC6FBEDAA2D2D3D97553 2019-07-08T22:17:41.445Z,1562624261.445 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,3*53 2019-07-08T22:17:41.634Z,1562624261.634 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,3*51 2019-07-08T22:17:42.023Z,1562624262.023 [Micromodem](INFO): Nmea in: $CADRQ,221742,1,9,0,64,1*4E 2019-07-08T22:17:42.024Z,1562624262.024 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,20BF235D000001005D00000400540100000000000000151D80030C5669BF3148E2FA22188B6A3173E5573572661C0BCBDFFAB423BD32D9A51E8904B0A920CE9A*05 2019-07-08T22:17:42.421Z,1562624262.421 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71 2019-07-08T22:17:42.821Z,1562624262.821 [Micromodem](INFO): Nmea in: $CADRQ,221743,1,9,0,64,2*4C 2019-07-08T22:17:42.822Z,1562624262.822 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,EF9F66414C9B9FD6761AD008C3E3DC4FCA2E4E25B6359B14B772C256504760B95108769F133EF900356E4A82FC7917069709FEF9BCD9C9E1D0AD78DEFCA2E5CB*08 2019-07-08T22:17:43.237Z,1562624263.237 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71 2019-07-08T22:17:43.641Z,1562624263.641 [Micromodem](INFO): Nmea in: $CADRQ,221743,1,9,0,64,3*4D 2019-07-08T22:17:43.641Z,1562624263.641 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,98CF72178E3B15D1468D1FDCB70B169565E1DDE4A2530F9435651DD9D56B635A84B0C315798D20A429BAC52CD122DD0CBBE78055BA2DBC6FBEDAA2D2D3D97553*09 2019-07-08T22:17:44.085Z,1562624264.085 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71 2019-07-08T22:17:44.437Z,1562624264.437 [Micromodem](INFO): Nmea in: $CATXP,192*48 2019-07-08T22:17:46.796Z,1562624266.796 [DataOverHttps](INFO): Sending 187 bytes from file Logs/20190708T220936/Courier0000.lzma 2019-07-08T22:17:48.073Z,1562624268.073 [Micromodem](INFO): Nmea in: $CATXF,192*5E 2019-07-08T22:17:48.478Z,1562624268.478 [Micromodem](INFO): Nmea in: $CAXST,6,20190708,221744.826597,3,0,200,4000,10000,1,1,9,1,3,3,3,192*44 2019-07-08T22:17:49.058Z,1562624269.058 [DataOverHttps](INFO): Moved sent file to Logs/20190708T220936/Courier0000.lzma.bak 2019-07-08T22:17:49.058Z,1562624269.058 [DataOverHttps](INFO): SBD MOMSN=11433983 2019-07-08T22:18:00.599Z,1562624280.599 [NAL9602](INFO): SBD MO Status=2, MOMSN=8096, MT Status=2, MTMSN=0 2019-07-08T22:18:00.599Z,1562624280.599 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-07-08T22:18:01.487Z,1562624281.487 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190708T221730/Courier0000.lzma 2019-07-08T22:18:02.293Z,1562624282.293 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Courier0000.lzma.bak 2019-07-08T22:18:02.293Z,1562624282.293 [DataOverHttps](INFO): SBD MOMSN=11433986 2019-07-08T22:18:15.876Z,1562624295.876 [DataOverHttps](INFO): Sending 215 bytes from file Logs/20190708T220257/Express0004.lzma 2019-07-08T22:18:16.681Z,1562624296.681 [DataOverHttps](INFO): Moved sent file to Logs/20190708T220257/Express0004.lzma.bak 2019-07-08T22:18:16.681Z,1562624296.681 [DataOverHttps](INFO): SBD MOMSN=11433990 2019-07-08T22:18:32.036Z,1562624312.036 [DataOverHttps](INFO): Sending 606 bytes from file Logs/20190708T220936/Express0001.lzma 2019-07-08T22:18:32.841Z,1562624312.841 [DataOverHttps](INFO): Moved sent file to Logs/20190708T220936/Express0001.lzma.bak 2019-07-08T22:18:32.841Z,1562624312.841 [DataOverHttps](INFO): SBD MOMSN=11433996 2019-07-08T22:18:46.657Z,1562624326.657 [Micromodem](ERROR): Buffer fill timout failure. 2019-07-08T22:18:47.875Z,1562624327.875 [DataOverHttps](INFO): Sending 323 bytes from file Logs/20190708T221730/Express0001.lzma 2019-07-08T22:18:48.674Z,1562624328.674 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0001.lzma.bak 2019-07-08T22:18:48.674Z,1562624328.674 [DataOverHttps](INFO): SBD MOMSN=11434005 2019-07-08T22:18:52.638Z,1562624332.638 [Default:CheckIn:Read_Iridium] Stopped 2019-07-08T22:18:52.638Z,1562624332.638 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-08T22:18:52.638Z,1562624332.638 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-08T22:18:56.718Z,1562624336.718 [NAL9602](INFO): SBD MO Status=0, MOMSN=8096, MT Status=0, MTMSN=0 2019-07-08T22:18:56.719Z,1562624336.719 [NAL9602](INFO): No messages in MT queue 2019-07-08T22:19:27.429Z,1562624367.429 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-08T22:23:52.916Z,1562624632.916 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-08T22:23:52.916Z,1562624632.916 [Default:CheckIn:C.Wait] Stopped 2019-07-08T22:23:52.916Z,1562624632.916 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-08T22:23:52.917Z,1562624632.917 [Default:CheckIn:D] Running Loop=1 2019-07-08T22:23:53.310Z,1562624633.310 [Default:CheckIn:D] Stopped 2019-07-08T22:23:53.310Z,1562624633.310 [Default:CheckIn:E] Running Loop=1 2019-07-08T22:23:53.691Z,1562624633.691 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 6.502122 min 2019-07-08T22:23:53.691Z,1562624633.691 [Default:CheckIn:E] Stopped 2019-07-08T22:23:53.691Z,1562624633.691 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-08T22:23:53.691Z,1562624633.691 [Default:CheckIn] Stopped 2019-07-08T22:23:53.691Z,1562624633.691 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-08T22:23:53.691Z,1562624633.691 [Default:CheckIn](INFO): Running loop #2 2019-07-08T22:23:53.692Z,1562624633.692 [Default:CheckIn] Running Loop=2 2019-07-08T22:23:53.692Z,1562624633.692 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-08T22:23:53.692Z,1562624633.692 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-08T22:23:55.291Z,1562624635.291 [NAL9602](DEBUG): Fix Requested 2019-07-08T22:23:55.683Z,1562624635.683 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,222343.00,A,3648.14114,N,12147.20838,W,0.058,347.52,080719,,,D*7A 2019-07-08T22:23:55.685Z,1562624635.685 [NAL9602](INFO): GPS fix at 20190708T222343: (36.802352, -121.786806) 2019-07-08T22:23:55.725Z,1562624635.725 [Default:CheckIn:Read_GPS] Stopped 2019-07-08T22:23:55.725Z,1562624635.725 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-08T22:24:05.619Z,1562624645.619 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190708T221730/Courier0003.lzma 2019-07-08T22:24:06.425Z,1562624646.425 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Courier0003.lzma.bak 2019-07-08T22:24:06.425Z,1562624646.425 [DataOverHttps](IMPORTANT): SBD MOMSN=11434011, MTMSN=20190708T222353 2019-07-08T22:24:14.080Z,1562624654.080 [DataOverHttps](INFO): Received command:maintain clear 2019-07-08T22:24:14.156Z,1562624654.156 [CommandLine](IMPORTANT): got command maintain clear 2019-07-08T22:24:14.309Z,1562624654.309 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2019-07-08T22:24:16.770Z,1562624656.770 [NAL9602](INFO): SBD MO Status=0, MOMSN=8097, MT Status=0, MTMSN=0 2019-07-08T22:24:16.770Z,1562624656.770 [NAL9602](INFO): No messages in MT queue 2019-07-08T22:24:20.555Z,1562624660.555 [DataOverHttps](INFO): Sending 209 bytes from file Logs/20190708T221730/Express0004.lzma 2019-07-08T22:24:21.361Z,1562624661.361 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0004.lzma.bak 2019-07-08T22:24:21.361Z,1562624661.361 [DataOverHttps](INFO): SBD MOMSN=11434015 2019-07-08T22:24:35.119Z,1562624675.119 [DataOverHttps](INFO): Sending 181 bytes from file Logs/20190708T221730/Express0007.lzma 2019-07-08T22:24:35.925Z,1562624675.925 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0007.lzma.bak 2019-07-08T22:24:35.925Z,1562624675.925 [DataOverHttps](INFO): SBD MOMSN=11434018 2019-07-08T22:24:38.650Z,1562624678.650 [Default:CheckIn:Read_Iridium] Stopped 2019-07-08T22:24:38.651Z,1562624678.651 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-08T22:24:38.651Z,1562624678.651 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-08T22:24:47.469Z,1562624687.469 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-08T22:25:15.431Z,1562624715.431 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout 2019-07-08T22:25:15.431Z,1562624715.431 [RDI_Pathfinder] Communications Fault, FailCount= 1 2019-07-08T22:25:15.431Z,1562624715.431 [RDI_Pathfinder](ERROR): Communications Fault 2019-07-08T22:25:15.432Z,1562624715.432 [RDI_Pathfinder](ERROR): Failed to parse: 2019-07-08T22:25:15.451Z,1562624715.451 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder 2019-07-08T22:25:15.828Z,1562624715.828 [RDI_Pathfinder](INFO): Powering down 2019-07-08T22:25:16.590Z,1562624716.590 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder 2019-07-08T22:25:16.590Z,1562624716.590 [RDI_Pathfinder] No Fault, FailCount= 1 2019-07-08T22:25:29.938Z,1562624729.938 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder 2019-07-08T22:29:39.271Z,1562624979.271 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-08T22:29:39.271Z,1562624979.271 [Default:CheckIn:C.Wait] Stopped 2019-07-08T22:29:39.271Z,1562624979.271 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-08T22:29:39.272Z,1562624979.272 [Default:CheckIn:D] Running Loop=1 2019-07-08T22:29:39.622Z,1562624979.622 [Default:CheckIn:D] Stopped 2019-07-08T22:29:39.622Z,1562624979.622 [Default:CheckIn:E] Running Loop=1 2019-07-08T22:29:40.039Z,1562624980.039 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 12.273998 min 2019-07-08T22:29:40.039Z,1562624980.039 [Default:CheckIn:E] Stopped 2019-07-08T22:29:40.039Z,1562624980.039 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-08T22:29:40.039Z,1562624980.039 [Default:CheckIn] Stopped 2019-07-08T22:29:40.039Z,1562624980.039 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-08T22:29:40.039Z,1562624980.039 [Default:CheckIn](INFO): Running loop #3 2019-07-08T22:29:40.039Z,1562624980.039 [Default:CheckIn] Running Loop=3 2019-07-08T22:29:40.040Z,1562624980.040 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-08T22:29:40.040Z,1562624980.040 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-08T22:29:41.631Z,1562624981.631 [NAL9602](DEBUG): Fix Requested 2019-07-08T22:29:42.032Z,1562624982.032 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,222929.00,A,3648.17396,N,12147.27266,W,0.136,282.63,080719,,,D*72 2019-07-08T22:29:42.035Z,1562624982.035 [NAL9602](INFO): GPS fix at 20190708T222929: (36.802899, -121.787878) 2019-07-08T22:29:42.068Z,1562624982.068 [Default:CheckIn:Read_GPS] Stopped 2019-07-08T22:29:42.068Z,1562624982.068 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-08T22:29:49.183Z,1562624989.183 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190708T221730/Courier0009.lzma 2019-07-08T22:29:49.985Z,1562624989.985 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Courier0009.lzma.bak 2019-07-08T22:29:49.985Z,1562624989.985 [DataOverHttps](INFO): SBD MOMSN=11434024 2019-07-08T22:30:03.027Z,1562625003.027 [NAL9602](INFO): SBD MO Status=0, MOMSN=8098, MT Status=0, MTMSN=0 2019-07-08T22:30:03.027Z,1562625003.027 [NAL9602](INFO): No messages in MT queue 2019-07-08T22:30:03.659Z,1562625003.659 [DataOverHttps](INFO): Sending 142 bytes from file Logs/20190708T221730/Express0010.lzma 2019-07-08T22:30:04.465Z,1562625004.465 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0010.lzma.bak 2019-07-08T22:30:04.465Z,1562625004.465 [DataOverHttps](INFO): SBD MOMSN=11434027 2019-07-08T22:30:07.107Z,1562625007.107 [Default:CheckIn:Read_Iridium] Stopped 2019-07-08T22:30:07.111Z,1562625007.111 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-08T22:30:07.111Z,1562625007.111 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-08T22:30:33.726Z,1562625033.726 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-08T22:33:18.578Z,1562625198.578 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-08T22:33:18.579Z,1562625198.579 [RDI_Pathfinder](ERROR): Failed to parse: :TS5431040,35.0, -0.1, 0.0,1448.9, 0 2019-07-08T22:35:07.686Z,1562625307.686 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-08T22:35:07.686Z,1562625307.686 [Default:CheckIn:C.Wait] Stopped 2019-07-08T22:35:07.686Z,1562625307.686 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-08T22:35:07.687Z,1562625307.687 [Default:CheckIn:D] Running Loop=1 2019-07-08T22:35:08.074Z,1562625308.074 [Default:CheckIn:D] Stopped 2019-07-08T22:35:08.074Z,1562625308.074 [Default:CheckIn:E] Running Loop=1 2019-07-08T22:35:08.491Z,1562625308.491 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 17.748195 min 2019-07-08T22:35:08.491Z,1562625308.491 [Default:CheckIn:E] Stopped 2019-07-08T22:35:08.492Z,1562625308.492 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-08T22:35:08.492Z,1562625308.492 [Default:CheckIn] Stopped 2019-07-08T22:35:08.492Z,1562625308.492 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-08T22:35:08.492Z,1562625308.492 [Default:CheckIn](INFO): Running loop #4 2019-07-08T22:35:08.492Z,1562625308.492 [Default:CheckIn] Running Loop=4 2019-07-08T22:35:08.492Z,1562625308.492 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-08T22:35:08.492Z,1562625308.492 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-08T22:35:10.083Z,1562625310.083 [NAL9602](DEBUG): Fix Requested 2019-07-08T22:35:10.489Z,1562625310.489 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,223458.00,A,3648.16574,N,12147.28054,W,0.467,169.40,080719,,,A*7C 2019-07-08T22:35:10.491Z,1562625310.491 [NAL9602](INFO): GPS fix at 20190708T223458: (36.802762, -121.788009) 2019-07-08T22:35:10.514Z,1562625310.514 [Default:CheckIn:Read_GPS] Stopped 2019-07-08T22:35:10.514Z,1562625310.514 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-08T22:35:17.483Z,1562625317.483 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190708T221730/Courier0012.lzma 2019-07-08T22:35:18.289Z,1562625318.289 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Courier0012.lzma.bak 2019-07-08T22:35:18.289Z,1562625318.289 [DataOverHttps](INFO): SBD MOMSN=11434032 2019-07-08T22:35:31.875Z,1562625331.875 [DataOverHttps](INFO): Sending 135 bytes from file Logs/20190708T221730/Express0013.lzma 2019-07-08T22:35:32.681Z,1562625332.681 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0013.lzma.bak 2019-07-08T22:35:32.681Z,1562625332.681 [DataOverHttps](INFO): SBD MOMSN=11434035 2019-07-08T22:35:35.201Z,1562625335.201 [Default:CheckIn:Read_Iridium] Stopped 2019-07-08T22:35:35.202Z,1562625335.202 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-08T22:35:35.202Z,1562625335.202 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-08T22:35:37.567Z,1562625337.567 [NAL9602](INFO): SBD MO Status=2, MOMSN=8099, MT Status=2, MTMSN=0 2019-07-08T22:35:37.571Z,1562625337.571 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-07-08T22:37:18.217Z,1562625438.217 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-08T22:37:18.217Z,1562625438.217 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 2019-07-08T22:37:26.298Z,1562625446.298 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-08T22:37:26.298Z,1562625446.298 [RDI_Pathfinder](ERROR): Failed to parse: :TS,190708154718 -0.1, 0.0,1448.9, 0 2019-07-08T22:37:44.888Z,1562625464.888 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-07-08T22:37:44.888Z,1562625464.888 [RDI_Pathfinder](ERROR): Failed to parse: :BD, , +0.00, +0.00, 0.00,734.98 2019-07-08T22:40:13.113Z,1562625613.113 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-08T22:40:19.412Z,1562625619.412 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.127689 2019-07-08T22:40:30.651Z,1562625630.651 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003273 2019-07-08T22:40:35.755Z,1562625635.755 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-08T22:40:35.755Z,1562625635.755 [Default:CheckIn:C.Wait] Stopped 2019-07-08T22:40:35.755Z,1562625635.755 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-08T22:40:35.756Z,1562625635.756 [Default:CheckIn:D] Running Loop=1 2019-07-08T22:40:36.174Z,1562625636.174 [Default:CheckIn:D] Stopped 2019-07-08T22:40:36.174Z,1562625636.174 [Default:CheckIn:E] Running Loop=1 2019-07-08T22:40:36.571Z,1562625636.571 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 23.216524 min 2019-07-08T22:40:36.571Z,1562625636.571 [Default:CheckIn:E] Stopped 2019-07-08T22:40:36.571Z,1562625636.571 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-08T22:40:36.571Z,1562625636.571 [Default:CheckIn] Stopped 2019-07-08T22:40:36.571Z,1562625636.571 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-08T22:40:36.571Z,1562625636.571 [Default:CheckIn](INFO): Running loop #5 2019-07-08T22:40:36.571Z,1562625636.571 [Default:CheckIn] Running Loop=5 2019-07-08T22:40:36.572Z,1562625636.572 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-08T22:40:36.572Z,1562625636.572 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-08T22:40:38.171Z,1562625638.171 [NAL9602](DEBUG): Fix Requested 2019-07-08T22:40:38.568Z,1562625638.568 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,224026.00,A,3648.16759,N,12147.28721,W,0.214,194.76,080719,,,A*7B 2019-07-08T22:40:38.570Z,1562625638.570 [NAL9602](INFO): GPS fix at 20190708T224026: (36.802793, -121.788120) 2019-07-08T22:40:38.603Z,1562625638.603 [Default:CheckIn:Read_GPS] Stopped 2019-07-08T22:40:38.603Z,1562625638.603 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-08T22:40:46.423Z,1562625646.423 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190708T221730/Courier0015.lzma 2019-07-08T22:40:47.229Z,1562625647.229 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Courier0015.lzma.bak 2019-07-08T22:40:47.229Z,1562625647.229 [DataOverHttps](INFO): SBD MOMSN=11434038 2019-07-08T22:41:11.232Z,1562625671.232 [DataOverHttps](INFO): Sending 227 bytes from file Logs/20190708T221730/Express0016.lzma 2019-07-08T22:41:11.297Z,1562625671.297 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-08T22:41:12.037Z,1562625672.037 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0016.lzma.bak 2019-07-08T22:41:12.037Z,1562625672.037 [DataOverHttps](INFO): SBD MOMSN=11434042 2019-07-08T22:41:17.414Z,1562625677.414 [Default:CheckIn:Read_Iridium] Stopped 2019-07-08T22:41:17.415Z,1562625677.415 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-08T22:41:17.415Z,1562625677.415 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-08T22:45:05.249Z,1562625905.249 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-08T22:45:05.249Z,1562625905.249 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19070815545740,35.0, -0.1, 8.9, 0 2019-07-08T22:45:33.971Z,1562625933.971 [RDI_Pathfinder](ERROR): Failed to parse: :SA, +0.00, +0.00, 0.00 2019-07-08T22:46:17.980Z,1562625977.980 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-08T22:46:17.980Z,1562625977.980 [Default:CheckIn:C.Wait] Stopped 2019-07-08T22:46:17.980Z,1562625977.980 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-08T22:46:17.980Z,1562625977.980 [Default:CheckIn:D] Running Loop=1 2019-07-08T22:46:18.382Z,1562625978.382 [Default:CheckIn:D] Stopped 2019-07-08T22:46:18.382Z,1562625978.382 [Default:CheckIn:E] Running Loop=1 2019-07-08T22:46:18.805Z,1562625978.805 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 28.919995 min 2019-07-08T22:46:18.805Z,1562625978.805 [Default:CheckIn:E] Stopped 2019-07-08T22:46:18.805Z,1562625978.805 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-08T22:46:18.806Z,1562625978.806 [Default:CheckIn] Stopped 2019-07-08T22:46:18.806Z,1562625978.806 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-08T22:46:18.806Z,1562625978.806 [Default:CheckIn](INFO): Running loop #6 2019-07-08T22:46:18.806Z,1562625978.806 [Default:CheckIn] Running Loop=6 2019-07-08T22:46:18.806Z,1562625978.806 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-08T22:46:18.806Z,1562625978.806 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-08T22:46:20.376Z,1562625980.376 [NAL9602](DEBUG): Fix Requested 2019-07-08T22:46:20.767Z,1562625980.767 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,224608.00,A,3648.17111,N,12147.28519,W,0.505,15.30,080719,,,A*4E 2019-07-08T22:46:20.769Z,1562625980.769 [NAL9602](INFO): GPS fix at 20190708T224608: (36.802852, -121.788087) 2019-07-08T22:46:20.818Z,1562625980.818 [Default:CheckIn:Read_GPS] Stopped 2019-07-08T22:46:20.819Z,1562625980.819 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-08T22:46:36.623Z,1562625996.623 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190708T221730/Courier0018.lzma 2019-07-08T22:46:37.266Z,1562625997.266 [RDI_Pathfinder](ERROR): Failed to parse: :SA, +0.00, +0.00, 0.00 2019-07-08T22:46:37.429Z,1562625997.429 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Courier0018.lzma.bak 2019-07-08T22:46:37.429Z,1562625997.429 [DataOverHttps](INFO): SBD MOMSN=11434046 2019-07-08T22:47:01.959Z,1562626021.959 [DataOverHttps](INFO): Sending 127 bytes from file Logs/20190708T221730/Express0019.lzma 2019-07-08T22:47:04.572Z,1562626024.572 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0019.lzma.bak 2019-07-08T22:47:04.572Z,1562626024.572 [DataOverHttps](INFO): SBD MOMSN=11434049 2019-07-08T22:47:07.993Z,1562626027.993 [Default:CheckIn:Read_Iridium] Stopped 2019-07-08T22:47:07.993Z,1562626027.993 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-08T22:47:07.994Z,1562626027.994 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-08T22:51:20.876Z,1562626280.876 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-07-08T22:51:20.877Z,1562626280.877 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-32768, 2019-07-08T22:51:22.857Z,1562626282.857 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-08T22:51:53.548Z,1562626313.548 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-08T22:52:08.527Z,1562626328.527 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-08T22:52:08.527Z,1562626328.527 [Default:CheckIn:C.Wait] Stopped 2019-07-08T22:52:08.527Z,1562626328.527 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-08T22:52:08.543Z,1562626328.543 [Default:CheckIn:D] Running Loop=1 2019-07-08T22:52:08.920Z,1562626328.920 [Default:CheckIn:D] Stopped 2019-07-08T22:52:08.920Z,1562626328.920 [Default:CheckIn:E] Running Loop=1 2019-07-08T22:52:09.335Z,1562626329.335 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 34.762276 min 2019-07-08T22:52:09.335Z,1562626329.335 [Default:CheckIn:E] Stopped 2019-07-08T22:52:09.336Z,1562626329.336 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-08T22:52:09.336Z,1562626329.336 [Default:CheckIn] Stopped 2019-07-08T22:52:09.336Z,1562626329.336 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-08T22:52:09.336Z,1562626329.336 [Default:CheckIn](INFO): Running loop #7 2019-07-08T22:52:09.336Z,1562626329.336 [Default:CheckIn] Running Loop=7 2019-07-08T22:52:09.336Z,1562626329.336 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-08T22:52:09.336Z,1562626329.336 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-08T22:52:10.931Z,1562626330.931 [NAL9602](DEBUG): Fix Requested 2019-07-08T22:52:11.323Z,1562626331.323 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,225158.00,A,3648.18387,N,12147.27006,W,4.587,52.89,080719,,,A*44 2019-07-08T22:52:11.325Z,1562626331.325 [NAL9602](INFO): GPS fix at 20190708T225158: (36.803064, -121.787834) 2019-07-08T22:52:11.364Z,1562626331.364 [Default:CheckIn:Read_GPS] Stopped 2019-07-08T22:52:11.364Z,1562626331.364 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-08T22:52:21.379Z,1562626341.379 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190708T221730/Courier0021.lzma 2019-07-08T22:52:22.185Z,1562626342.185 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Courier0021.lzma.bak 2019-07-08T22:52:22.185Z,1562626342.185 [DataOverHttps](INFO): SBD MOMSN=11434052 2019-07-08T22:52:45.495Z,1562626365.495 [DataOverHttps](INFO): Sending 209 bytes from file Logs/20190708T221730/Express0022.lzma 2019-07-08T22:52:46.302Z,1562626366.302 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0022.lzma.bak 2019-07-08T22:52:46.302Z,1562626366.302 [DataOverHttps](INFO): SBD MOMSN=11434055 2019-07-08T22:52:51.755Z,1562626371.755 [Default:CheckIn:Read_Iridium] Stopped 2019-07-08T22:52:51.755Z,1562626371.755 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-08T22:52:51.755Z,1562626371.755 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-08T22:54:01.230Z,1562626441.230 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-08T22:54:01.230Z,1562626441.230 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19070816035340,35.0, -0.1, 0.0,1448.9A, 0.00, 0.00, 0.00, 0.00, 0.00 2019-07-08T22:56:21.859Z,1562626581.859 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-08T22:56:21.859Z,1562626581.859 [RDI_Pathfinder](ERROR): Failed to parse: :TS32768,V 2019-07-08T22:57:01.912Z,1562626621.912 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-07-08T22:57:01.913Z,1562626621.913 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0.00, +0. 2019-07-08T22:57:06.288Z,1562626626.288 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-08T22:57:06.288Z,1562626626.288 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19070816065, -0.1, 0.0,1448.9, 0 2019-07-08T22:57:13.934Z,1562626633.934 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-08T22:57:44.645Z,1562626664.645 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-08T22:57:52.343Z,1562626672.343 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-08T22:57:52.343Z,1562626672.343 [Default:CheckIn:C.Wait] Stopped 2019-07-08T22:57:52.343Z,1562626672.343 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-08T22:57:52.343Z,1562626672.343 [Default:CheckIn:D] Running Loop=1 2019-07-08T22:57:52.747Z,1562626672.747 [Default:CheckIn:D] Stopped 2019-07-08T22:57:52.747Z,1562626672.747 [Default:CheckIn:E] Running Loop=1 2019-07-08T22:57:53.170Z,1562626673.170 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 40.492737 min 2019-07-08T22:57:53.170Z,1562626673.170 [Default:CheckIn:E] Stopped 2019-07-08T22:57:53.171Z,1562626673.171 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-08T22:57:53.171Z,1562626673.171 [Default:CheckIn] Stopped 2019-07-08T22:57:53.171Z,1562626673.171 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-08T22:57:53.175Z,1562626673.175 [Default:CheckIn](INFO): Running loop #8 2019-07-08T22:57:53.175Z,1562626673.175 [Default:CheckIn] Running Loop=8 2019-07-08T22:57:53.175Z,1562626673.175 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-08T22:57:53.176Z,1562626673.176 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-08T22:57:54.759Z,1562626674.759 [NAL9602](DEBUG): Fix Requested 2019-07-08T22:57:55.147Z,1562626675.147 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,225742.00,A,3648.21395,N,12147.23610,W,1.186,34.46,080719,,,A*46 2019-07-08T22:57:55.150Z,1562626675.150 [NAL9602](INFO): GPS fix at 20190708T225742: (36.803566, -121.787268) 2019-07-08T22:57:55.217Z,1562626675.217 [Default:CheckIn:Read_GPS] Stopped 2019-07-08T22:57:55.217Z,1562626675.217 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-08T22:58:10.419Z,1562626690.419 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190708T221730/Courier0024.lzma 2019-07-08T22:58:11.225Z,1562626691.225 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Courier0024.lzma.bak 2019-07-08T22:58:11.225Z,1562626691.225 [DataOverHttps](INFO): SBD MOMSN=11434059 2019-07-08T22:58:25.849Z,1562626705.849 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-07-08T22:58:25.927Z,1562626705.927 [NAL9602](FAULT): received: +CSQ:0 OK99, 2, 0, 0, 0 OK 2019-07-08T22:58:25.927Z,1562626705.927 [NAL9602] Data Fault, FailCount= 1 2019-07-08T22:58:25.928Z,1562626705.928 [NAL9602](ERROR): Data Fault 2019-07-08T22:58:26.024Z,1562626706.024 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-08T22:58:26.253Z,1562626706.253 [NAL9602](INFO): Powering down 2019-07-08T22:58:27.114Z,1562626707.114 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-08T22:58:27.114Z,1562626707.114 [NAL9602] No Fault, FailCount= 1 2019-07-08T22:58:41.439Z,1562626721.439 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20190708T221730/Express0025.lzma 2019-07-08T22:58:42.245Z,1562626722.245 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0025.lzma.bak 2019-07-08T22:58:42.245Z,1562626722.245 [DataOverHttps](INFO): SBD MOMSN=11434062 2019-07-08T22:58:44.948Z,1562626724.948 [Default:CheckIn:Read_Iridium] Stopped 2019-07-08T22:58:44.948Z,1562626724.948 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-08T22:58:44.948Z,1562626724.948 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-08T22:58:56.553Z,1562626736.553 [NAL9602](INFO): Powering up NAL9602 2019-07-08T22:59:07.462Z,1562626747.462 [NAL9602](INFO): NAL9602 initialized 2019-07-08T22:59:38.579Z,1562626778.579 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-08T23:00:58.580Z,1562626858.580 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-08T23:00:58.580Z,1562626858.580 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-07-08T23:03:45.433Z,1562627025.433 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-08T23:03:45.433Z,1562627025.433 [Default:CheckIn:C.Wait] Stopped 2019-07-08T23:03:45.433Z,1562627025.433 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-08T23:03:45.434Z,1562627025.434 [Default:CheckIn:D] Running Loop=1 2019-07-08T23:03:45.850Z,1562627025.850 [Default:CheckIn:D] Stopped 2019-07-08T23:03:45.850Z,1562627025.850 [Default:CheckIn:E] Running Loop=1 2019-07-08T23:03:46.255Z,1562627026.255 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 46.377795 min 2019-07-08T23:03:46.255Z,1562627026.255 [Default:CheckIn:E] Stopped 2019-07-08T23:03:46.255Z,1562627026.255 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-08T23:03:46.255Z,1562627026.255 [Default:CheckIn] Stopped 2019-07-08T23:03:46.255Z,1562627026.255 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-08T23:03:46.256Z,1562627026.256 [Default:CheckIn](INFO): Running loop #9 2019-07-08T23:03:46.256Z,1562627026.256 [Default:CheckIn] Running Loop=9 2019-07-08T23:03:46.256Z,1562627026.256 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-08T23:03:46.256Z,1562627026.256 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-08T23:03:47.847Z,1562627027.847 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:03:49.457Z,1562627029.457 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-08T23:03:50.280Z,1562627030.280 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:03:53.099Z,1562627033.099 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:03:55.939Z,1562627035.939 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:03:59.171Z,1562627039.171 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:01.999Z,1562627041.999 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:05.219Z,1562627045.219 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:08.055Z,1562627048.055 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:10.883Z,1562627050.883 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:13.307Z,1562627053.307 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:16.131Z,1562627056.131 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:19.367Z,1562627059.367 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:22.191Z,1562627062.191 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:25.027Z,1562627065.027 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:27.847Z,1562627067.847 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:31.079Z,1562627071.079 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:33.911Z,1562627073.911 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:37.143Z,1562627077.143 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:39.963Z,1562627079.963 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:43.207Z,1562627083.207 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:46.031Z,1562627086.031 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:49.263Z,1562627089.263 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:52.095Z,1562627092.095 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:55.319Z,1562627095.319 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:04:58.147Z,1562627098.147 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:01.383Z,1562627101.383 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:04.207Z,1562627104.207 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:07.039Z,1562627107.039 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:09.879Z,1562627109.879 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:13.099Z,1562627113.099 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:15.931Z,1562627115.931 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:19.160Z,1562627119.160 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:21.987Z,1562627121.987 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:25.223Z,1562627125.223 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:28.047Z,1562627128.047 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:31.271Z,1562627131.271 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:34.111Z,1562627134.111 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:37.335Z,1562627137.335 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:40.163Z,1562627140.163 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:42.987Z,1562627142.987 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:45.823Z,1562627145.823 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:47.839Z,1562627147.839 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:49.879Z,1562627149.879 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:53.095Z,1562627153.095 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:55.931Z,1562627155.931 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:05:59.155Z,1562627159.155 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:01.983Z,1562627161.983 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:05.211Z,1562627165.211 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:08.039Z,1562627168.039 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:10.871Z,1562627170.871 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:13.299Z,1562627173.299 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:16.115Z,1562627176.115 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:19.347Z,1562627179.347 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:22.183Z,1562627182.183 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:25.007Z,1562627185.007 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:27.839Z,1562627187.839 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:29.896Z,1562627189.896 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:33.087Z,1562627193.087 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:35.937Z,1562627195.937 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:39.159Z,1562627199.159 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:41.999Z,1562627201.999 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:45.219Z,1562627205.219 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:48.035Z,1562627208.035 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:50.871Z,1562627210.871 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:54.099Z,1562627214.099 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:06:56.927Z,1562627216.927 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:00.155Z,1562627220.155 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:02.983Z,1562627222.983 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:05.811Z,1562627225.811 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:07.835Z,1562627227.835 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:09.875Z,1562627229.875 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:13.087Z,1562627233.087 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:15.935Z,1562627235.935 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:19.160Z,1562627239.160 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:21.975Z,1562627241.975 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:25.203Z,1562627245.203 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:28.031Z,1562627248.031 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:31.271Z,1562627251.271 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:34.099Z,1562627254.099 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:37.323Z,1562627257.323 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:40.167Z,1562627260.167 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:43.383Z,1562627263.383 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:46.215Z,1562627266.215 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:49.043Z,1562627269.043 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:51.871Z,1562627271.871 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:55.103Z,1562627275.103 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:07:57.931Z,1562627277.931 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:08:01.163Z,1562627281.163 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:08:03.991Z,1562627283.991 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:08:07.219Z,1562627287.219 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:08:10.051Z,1562627290.051 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:08:13.283Z,1562627293.283 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:08:16.107Z,1562627296.107 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:08:19.339Z,1562627299.339 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:08:22.167Z,1562627302.167 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:08:25.007Z,1562627305.007 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:08:27.827Z,1562627307.827 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:08:29.863Z,1562627309.863 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:08:31.867Z,1562627311.867 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:08:35.095Z,1562627315.095 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:08:37.927Z,1562627317.927 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:08:41.159Z,1562627321.159 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:08:43.979Z,1562627323.979 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:08:46.421Z,1562627326.421 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-08T23:03:46.3Z 2019-07-08T23:08:46.421Z,1562627326.421 [Default:CheckIn:Read_GPS] Stopped 2019-07-08T23:08:46.421Z,1562627326.421 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-08T23:08:55.447Z,1562627335.447 [DataOverHttps](INFO): Sending 243 bytes from file Logs/20190708T221730/Express0028.lzma 2019-07-08T23:08:56.253Z,1562627336.253 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0028.lzma.bak 2019-07-08T23:08:56.253Z,1562627336.253 [DataOverHttps](INFO): SBD MOMSN=11434066 2019-07-08T23:09:01.044Z,1562627341.044 [Default:CheckIn:Read_Iridium] Stopped 2019-07-08T23:09:01.044Z,1562627341.044 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-08T23:09:01.044Z,1562627341.044 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-08T23:09:17.145Z,1562627357.145 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-08T23:14:01.601Z,1562627641.601 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-08T23:14:01.601Z,1562627641.601 [Default:CheckIn:C.Wait] Stopped 2019-07-08T23:14:01.601Z,1562627641.601 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-08T23:14:01.602Z,1562627641.602 [Default:CheckIn:D] Running Loop=1 2019-07-08T23:14:02.022Z,1562627642.022 [Default:CheckIn:D] Stopped 2019-07-08T23:14:02.022Z,1562627642.022 [Default:CheckIn:E] Running Loop=1 2019-07-08T23:14:02.399Z,1562627642.399 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 56.647327 min 2019-07-08T23:14:02.399Z,1562627642.399 [Default:CheckIn:E] Stopped 2019-07-08T23:14:02.400Z,1562627642.400 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-08T23:14:02.400Z,1562627642.400 [Default:CheckIn] Stopped 2019-07-08T23:14:02.400Z,1562627642.400 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-08T23:14:02.400Z,1562627642.400 [Default:CheckIn](INFO): Running loop #10 2019-07-08T23:14:02.400Z,1562627642.400 [Default:CheckIn] Running Loop=10 2019-07-08T23:14:02.400Z,1562627642.400 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-08T23:14:02.400Z,1562627642.400 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-08T23:14:03.993Z,1562627643.993 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-07-08T23:14:03.993Z,1562627643.993 [NAL9602] Data Fault, FailCount= 1 2019-07-08T23:14:03.993Z,1562627643.993 [NAL9602](ERROR): Data Fault 2019-07-08T23:14:04.040Z,1562627644.040 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-08T23:14:04.412Z,1562627644.412 [NAL9602](INFO): Powering down 2019-07-08T23:14:05.234Z,1562627645.234 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-08T23:14:05.234Z,1562627645.234 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19070816235740,35.0, -0.1, .9, 0 2019-07-08T23:14:05.252Z,1562627645.252 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-08T23:14:05.252Z,1562627645.252 [NAL9602] No Fault, FailCount= 1 2019-07-08T23:14:34.693Z,1562627674.693 [NAL9602](INFO): Powering up NAL9602 2019-07-08T23:14:45.605Z,1562627685.605 [NAL9602](INFO): NAL9602 initialized 2019-07-08T23:14:46.423Z,1562627686.423 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:16:24.231Z,1562627784.231 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-07-08T23:19:02.573Z,1562627942.573 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-08T23:14:02.4Z 2019-07-08T23:19:02.574Z,1562627942.574 [Default:CheckIn:Read_GPS] Stopped 2019-07-08T23:19:02.574Z,1562627942.574 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-08T23:19:11.275Z,1562627951.275 [DataOverHttps](INFO): Sending 168 bytes from file Logs/20190708T221730/Express0031.lzma 2019-07-08T23:19:12.081Z,1562627952.081 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0031.lzma.bak 2019-07-08T23:19:12.081Z,1562627952.081 [DataOverHttps](INFO): SBD MOMSN=11434071 2019-07-08T23:19:14.714Z,1562627954.714 [Default:CheckIn:Read_Iridium] Stopped 2019-07-08T23:19:14.714Z,1562627954.714 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-08T23:19:14.714Z,1562627954.714 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-08T23:19:49.241Z,1562627989.241 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-08T23:20:19.945Z,1562628019.945 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-08T23:21:24.209Z,1562628084.209 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-08T23:21:24.209Z,1562628084.209 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-07-08T23:22:11.520Z,1562628131.520 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-07-08T23:22:11.522Z,1562628131.522 [BPC1](INFO): Received data from all battery sticks. 2019-07-08T23:23:58.263Z,1562628238.263 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout 2019-07-08T23:23:58.263Z,1562628238.263 [RDI_Pathfinder] Communications Fault, FailCount= 1 2019-07-08T23:23:58.263Z,1562628238.263 [RDI_Pathfinder](ERROR): Communications Fault 2019-07-08T23:23:58.264Z,1562628238.264 [RDI_Pathfinder](ERROR): Failed to parse: 2019-07-08T23:23:58.287Z,1562628238.287 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder 2019-07-08T23:23:58.639Z,1562628238.639 [RDI_Pathfinder](INFO): Powering down 2019-07-08T23:23:59.399Z,1562628239.399 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder 2019-07-08T23:23:59.399Z,1562628239.399 [RDI_Pathfinder] No Fault, FailCount= 1 2019-07-08T23:24:12.724Z,1562628252.724 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder 2019-07-08T23:24:15.150Z,1562628255.150 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-08T23:24:15.150Z,1562628255.150 [Default:CheckIn:C.Wait] Stopped 2019-07-08T23:24:15.150Z,1562628255.150 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-08T23:24:15.151Z,1562628255.151 [Default:CheckIn:D] Running Loop=1 2019-07-08T23:24:15.550Z,1562628255.550 [Default:CheckIn:D] Stopped 2019-07-08T23:24:15.550Z,1562628255.550 [Default:CheckIn:E] Running Loop=1 2019-07-08T23:24:15.967Z,1562628255.967 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 66.872795 min 2019-07-08T23:24:15.967Z,1562628255.967 [Default:CheckIn:E] Stopped 2019-07-08T23:24:15.968Z,1562628255.968 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-08T23:24:15.968Z,1562628255.968 [Default:CheckIn] Stopped 2019-07-08T23:24:15.968Z,1562628255.968 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-08T23:24:15.968Z,1562628255.968 [Default:CheckIn](INFO): Running loop #11 2019-07-08T23:24:15.968Z,1562628255.968 [Default:CheckIn] Running Loop=11 2019-07-08T23:24:15.968Z,1562628255.968 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-08T23:24:15.968Z,1562628255.968 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-08T23:24:17.559Z,1562628257.559 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:24:48.654Z,1562628288.654 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-07-08T23:24:48.727Z,1562628288.727 [NAL9602](FAULT): received: +CSQ:0 OK99, 2, 0, 0, 0 OK 2019-07-08T23:24:48.728Z,1562628288.728 [NAL9602] Data Fault, FailCount= 2 2019-07-08T23:24:48.728Z,1562628288.728 [NAL9602](ERROR): Data Fault 2019-07-08T23:24:48.836Z,1562628288.836 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-08T23:24:49.063Z,1562628289.063 [NAL9602](INFO): Powering down 2019-07-08T23:24:49.934Z,1562628289.934 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-08T23:24:49.934Z,1562628289.934 [NAL9602] No Fault, FailCount= 2 2019-07-08T23:25:19.353Z,1562628319.353 [NAL9602](INFO): Powering up NAL9602 2019-07-08T23:25:30.269Z,1562628330.269 [NAL9602](INFO): NAL9602 initialized 2019-07-08T23:25:31.077Z,1562628331.077 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-07-08T23:25:31.077Z,1562628331.077 [NAL9602] Data Fault, FailCount= 3 2019-07-08T23:25:31.077Z,1562628331.077 [NAL9602](ERROR): Data Fault 2019-07-08T23:25:31.120Z,1562628331.120 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-08T23:25:31.477Z,1562628331.477 [NAL9602](INFO): Powering down 2019-07-08T23:25:32.342Z,1562628332.342 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-08T23:25:32.343Z,1562628332.343 [NAL9602] No Fault, FailCount= 3 2019-07-08T23:26:01.777Z,1562628361.777 [NAL9602](INFO): Powering up NAL9602 2019-07-08T23:26:12.697Z,1562628372.697 [NAL9602](INFO): NAL9602 initialized 2019-07-08T23:26:13.499Z,1562628373.499 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:28:45.811Z,1562628525.811 [NAL9602](INFO): SBD MO Status=2, MOMSN=8099, MT Status=2, MTMSN=0 2019-07-08T23:28:45.811Z,1562628525.811 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-07-08T23:29:16.128Z,1562628556.128 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-08T23:24:15.0Z 2019-07-08T23:29:16.128Z,1562628556.128 [Default:CheckIn:Read_GPS] Stopped 2019-07-08T23:29:16.129Z,1562628556.129 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-08T23:29:19.777Z,1562628559.777 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-08T23:29:22.899Z,1562628562.899 [DataOverHttps](INFO): Sending 186 bytes from file Logs/20190708T221730/Courier0033.lzma 2019-07-08T23:29:23.705Z,1562628563.705 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Courier0033.lzma.bak 2019-07-08T23:29:23.705Z,1562628563.705 [DataOverHttps](INFO): SBD MOMSN=11434075 2019-07-08T23:29:40.703Z,1562628580.703 [DataOverHttps](INFO): Sending 260 bytes from file Logs/20190708T221730/Express0034.lzma 2019-07-08T23:29:41.511Z,1562628581.511 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0034.lzma.bak 2019-07-08T23:29:41.511Z,1562628581.511 [DataOverHttps](INFO): SBD MOMSN=11434077 2019-07-08T23:29:44.862Z,1562628584.862 [Default:CheckIn:Read_Iridium] Stopped 2019-07-08T23:29:44.862Z,1562628584.862 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-08T23:29:44.862Z,1562628584.862 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-08T23:29:50.481Z,1562628590.481 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-08T23:33:42.030Z,1562628822.030 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-07-08T23:33:42.031Z,1562628822.031 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0.00, +0.00, , 0.00,568.99 2019-07-08T23:34:45.428Z,1562628885.428 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-08T23:34:45.428Z,1562628885.428 [Default:CheckIn:C.Wait] Stopped 2019-07-08T23:34:45.428Z,1562628885.428 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-08T23:34:45.428Z,1562628885.428 [Default:CheckIn:D] Running Loop=1 2019-07-08T23:34:45.846Z,1562628885.846 [Default:CheckIn:D] Stopped 2019-07-08T23:34:45.846Z,1562628885.846 [Default:CheckIn:E] Running Loop=1 2019-07-08T23:34:46.245Z,1562628886.245 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 77.377726 min 2019-07-08T23:34:46.245Z,1562628886.245 [Default:CheckIn:E] Stopped 2019-07-08T23:34:46.245Z,1562628886.245 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-08T23:34:46.245Z,1562628886.245 [Default:CheckIn] Stopped 2019-07-08T23:34:46.245Z,1562628886.245 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-08T23:34:46.245Z,1562628886.245 [Default:CheckIn](INFO): Running loop #12 2019-07-08T23:34:46.245Z,1562628886.245 [Default:CheckIn] Running Loop=12 2019-07-08T23:34:46.245Z,1562628886.245 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-08T23:34:46.246Z,1562628886.246 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-08T23:34:47.843Z,1562628887.843 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:35:18.937Z,1562628918.937 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-07-08T23:35:19.015Z,1562628919.015 [NAL9602](FAULT): received: +CSQ:0 OK99, 2, 0, 0, 0 OK 2019-07-08T23:35:19.015Z,1562628919.015 [NAL9602] Data Fault, FailCount= 4 2019-07-08T23:35:19.015Z,1562628919.015 [NAL9602](ERROR): Data Fault 2019-07-08T23:35:19.098Z,1562628919.098 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-08T23:35:19.341Z,1562628919.341 [NAL9602](INFO): Powering down 2019-07-08T23:35:20.187Z,1562628920.187 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-08T23:35:20.187Z,1562628920.187 [NAL9602] No Fault, FailCount= 4 2019-07-08T23:35:49.637Z,1562628949.637 [NAL9602](INFO): Powering up NAL9602 2019-07-08T23:36:00.549Z,1562628960.549 [NAL9602](INFO): NAL9602 initialized 2019-07-08T23:36:01.375Z,1562628961.375 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:39:46.402Z,1562629186.402 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-08T23:34:46.2Z 2019-07-08T23:39:46.402Z,1562629186.402 [Default:CheckIn:Read_GPS] Stopped 2019-07-08T23:39:46.402Z,1562629186.402 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-08T23:39:49.617Z,1562629189.617 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-08T23:39:54.987Z,1562629194.987 [DataOverHttps](INFO): Sending 243 bytes from file Logs/20190708T221730/Express0037.lzma 2019-07-08T23:39:55.793Z,1562629195.793 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0037.lzma.bak 2019-07-08T23:39:55.793Z,1562629195.793 [DataOverHttps](INFO): SBD MOMSN=11434083 2019-07-08T23:39:58.526Z,1562629198.526 [Default:CheckIn:Read_Iridium] Stopped 2019-07-08T23:39:58.526Z,1562629198.526 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-08T23:39:58.526Z,1562629198.526 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-08T23:40:20.324Z,1562629220.324 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-08T23:44:19.117Z,1562629459.117 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-08T23:44:19.117Z,1562629459.117 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19070816541124,35.0, -.0,1448.9, 0 2019-07-08T23:44:59.109Z,1562629499.109 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-08T23:44:59.109Z,1562629499.109 [Default:CheckIn:C.Wait] Stopped 2019-07-08T23:44:59.109Z,1562629499.109 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-08T23:44:59.109Z,1562629499.109 [Default:CheckIn:D] Running Loop=1 2019-07-08T23:44:59.508Z,1562629499.508 [Default:CheckIn:D] Stopped 2019-07-08T23:44:59.508Z,1562629499.508 [Default:CheckIn:E] Running Loop=1 2019-07-08T23:44:59.922Z,1562629499.922 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 87.605428 min 2019-07-08T23:44:59.922Z,1562629499.922 [Default:CheckIn:E] Stopped 2019-07-08T23:44:59.922Z,1562629499.922 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-08T23:44:59.922Z,1562629499.922 [Default:CheckIn] Stopped 2019-07-08T23:44:59.922Z,1562629499.922 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-08T23:44:59.923Z,1562629499.923 [Default:CheckIn](INFO): Running loop #13 2019-07-08T23:44:59.923Z,1562629499.923 [Default:CheckIn] Running Loop=13 2019-07-08T23:44:59.923Z,1562629499.923 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-08T23:44:59.923Z,1562629499.923 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-08T23:45:01.501Z,1562629501.501 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-07-08T23:45:01.501Z,1562629501.501 [NAL9602] Data Fault, FailCount= 5 2019-07-08T23:45:01.502Z,1562629501.502 [NAL9602](ERROR): Data Fault 2019-07-08T23:45:01.560Z,1562629501.560 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-08T23:45:01.560Z,1562629501.560 [CBIT](CRITICAL): Data Fault in component: NAL9602 2019-07-08T23:45:01.905Z,1562629501.905 [NAL9602](INFO): Powering down 2019-07-08T23:45:01.957Z,1562629501.957 [CommandLine](FAULT): Scheduling is paused 2019-07-08T23:45:01.959Z,1562629501.959 [CBIT](INFO): Critical error at 20190708T234501 2019-07-08T23:47:01.571Z,1562629621.571 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-08T23:47:01.572Z,1562629621.572 [NAL9602] No Fault, FailCount= 5 2019-07-08T23:47:01.909Z,1562629621.909 [NAL9602](INFO): Powering up NAL9602 2019-07-08T23:47:12.817Z,1562629632.817 [NAL9602](INFO): NAL9602 initialized 2019-07-08T23:47:13.663Z,1562629633.663 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:48:59.089Z,1562629739.089 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-08T23:48:59.089Z,1562629739.089 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-07-08T23:50:00.130Z,1562629800.130 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-08T23:44:59.9Z 2019-07-08T23:50:00.130Z,1562629800.130 [Default:CheckIn:Read_GPS] Stopped 2019-07-08T23:50:00.131Z,1562629800.131 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-08T23:50:15.155Z,1562629815.155 [DataOverHttps](INFO): Sending 93 bytes from file Logs/20190708T221730/Courier0039.lzma 2019-07-08T23:50:15.961Z,1562629815.961 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Courier0039.lzma.bak 2019-07-08T23:50:15.961Z,1562629815.961 [DataOverHttps](INFO): SBD MOMSN=11434088 2019-07-08T23:50:32.715Z,1562629832.715 [DataOverHttps](INFO): Sending 246 bytes from file Logs/20190708T221730/Express0040.lzma 2019-07-08T23:50:33.521Z,1562629833.521 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0040.lzma.bak 2019-07-08T23:50:33.521Z,1562629833.521 [DataOverHttps](INFO): SBD MOMSN=11434091 2019-07-08T23:50:36.070Z,1562629836.070 [Default:CheckIn:Read_Iridium] Stopped 2019-07-08T23:50:36.070Z,1562629836.070 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-08T23:50:36.070Z,1562629836.070 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-08T23:51:57.688Z,1562629917.688 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-08T23:51:57.688Z,1562629917.688 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-07-08T23:52:14.659Z,1562629934.659 [RDI_Pathfinder](ERROR): Failed to parse: 68,-32768,-32768,V 2019-07-08T23:52:16.225Z,1562629936.225 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-08T23:52:46.929Z,1562629966.929 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-08T23:55:36.675Z,1562630136.675 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-08T23:55:36.675Z,1562630136.675 [Default:CheckIn:C.Wait] Stopped 2019-07-08T23:55:36.675Z,1562630136.675 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-08T23:55:36.676Z,1562630136.676 [Default:CheckIn:D] Running Loop=1 2019-07-08T23:55:37.037Z,1562630137.037 [Default:CheckIn:D] Stopped 2019-07-08T23:55:37.037Z,1562630137.037 [Default:CheckIn:E] Running Loop=1 2019-07-08T23:55:37.442Z,1562630137.442 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 98.230908 min 2019-07-08T23:55:37.443Z,1562630137.443 [Default:CheckIn:E] Stopped 2019-07-08T23:55:37.443Z,1562630137.443 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-08T23:55:37.443Z,1562630137.443 [Default:CheckIn] Stopped 2019-07-08T23:55:37.443Z,1562630137.443 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-08T23:55:37.443Z,1562630137.443 [Default:CheckIn](INFO): Running loop #14 2019-07-08T23:55:37.443Z,1562630137.443 [Default:CheckIn] Running Loop=14 2019-07-08T23:55:37.444Z,1562630137.444 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-08T23:55:37.444Z,1562630137.444 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-08T23:55:39.047Z,1562630139.047 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:55:57.674Z,1562630157.674 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-32768,-32768,V 2019-07-08T23:56:10.137Z,1562630170.137 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-07-08T23:56:10.215Z,1562630170.215 [NAL9602](FAULT): received: +CSQ:0 OK99, 2, 0, 0, 0 OK 2019-07-08T23:56:10.215Z,1562630170.215 [NAL9602] Data Fault, FailCount= 1 2019-07-08T23:56:10.215Z,1562630170.215 [NAL9602](ERROR): Data Fault 2019-07-08T23:56:10.324Z,1562630170.324 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-08T23:56:10.541Z,1562630170.541 [NAL9602](INFO): Powering down 2019-07-08T23:56:11.402Z,1562630171.402 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-08T23:56:11.402Z,1562630171.402 [NAL9602] No Fault, FailCount= 1 2019-07-08T23:56:40.847Z,1562630200.847 [NAL9602](INFO): Powering up NAL9602 2019-07-08T23:56:51.753Z,1562630211.753 [NAL9602](INFO): NAL9602 initialized 2019-07-08T23:56:52.575Z,1562630212.575 [NAL9602](DEBUG): Fix Requested 2019-07-08T23:57:52.397Z,1562630272.397 [RDI_Pathfinder](ERROR): only read 0 of 4 data items 2019-07-08T23:57:52.398Z,1562630272.398 [RDI_Pathfinder](ERROR): Failed to parse: :RA 0.00, 0.00, 0.00 2019-07-09T00:00:37.646Z,1562630437.646 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-08T23:55:37.4Z 2019-07-09T00:00:37.646Z,1562630437.646 [Default:CheckIn:Read_GPS] Stopped 2019-07-09T00:00:37.647Z,1562630437.647 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-09T00:00:41.689Z,1562630441.689 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-09T00:00:45.499Z,1562630445.499 [DataOverHttps](INFO): Sending 244 bytes from file Logs/20190708T221730/Express0043.lzma 2019-07-09T00:00:46.305Z,1562630446.305 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0043.lzma.bak 2019-07-09T00:00:46.305Z,1562630446.305 [DataOverHttps](INFO): SBD MOMSN=11434097 2019-07-09T00:00:48.998Z,1562630448.998 [Default:CheckIn:Read_Iridium] Stopped 2019-07-09T00:00:48.998Z,1562630448.998 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-09T00:00:48.998Z,1562630448.998 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-09T00:01:12.389Z,1562630472.389 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-09T00:01:31.081Z,1562630491.081 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-07-09T00:01:31.081Z,1562630491.081 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0.00, 37.79 2019-07-09T00:02:37.674Z,1562630557.674 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-07-09T00:02:37.674Z,1562630557.674 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-3768,V 2019-07-09T00:05:17.678Z,1562630717.678 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-07-09T00:05:17.678Z,1562630717.678 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0. +0.00, +0.00, 0.00,2464.73 2019-07-09T00:05:49.568Z,1562630749.568 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-09T00:05:49.568Z,1562630749.568 [Default:CheckIn:C.Wait] Stopped 2019-07-09T00:05:49.569Z,1562630749.569 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-09T00:05:49.569Z,1562630749.569 [Default:CheckIn:D] Running Loop=1 2019-07-09T00:05:49.983Z,1562630749.983 [Default:CheckIn:D] Stopped 2019-07-09T00:05:49.983Z,1562630749.983 [Default:CheckIn:E] Running Loop=1 2019-07-09T00:05:50.368Z,1562630750.368 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 108.446680 min 2019-07-09T00:05:50.369Z,1562630750.369 [Default:CheckIn:E] Stopped 2019-07-09T00:05:50.369Z,1562630750.369 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-09T00:05:50.369Z,1562630750.369 [Default:CheckIn] Stopped 2019-07-09T00:05:50.369Z,1562630750.369 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-09T00:05:50.369Z,1562630750.369 [Default:CheckIn](INFO): Running loop #15 2019-07-09T00:05:50.369Z,1562630750.369 [Default:CheckIn] Running Loop=15 2019-07-09T00:05:50.369Z,1562630750.369 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-09T00:05:50.369Z,1562630750.369 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-09T00:05:51.958Z,1562630751.958 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-07-09T00:05:51.959Z,1562630751.959 [NAL9602] Data Fault, FailCount= 2 2019-07-09T00:05:51.959Z,1562630751.959 [NAL9602](ERROR): Data Fault 2019-07-09T00:05:52.015Z,1562630752.015 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-09T00:05:52.369Z,1562630752.369 [NAL9602](INFO): Powering down 2019-07-09T00:05:53.212Z,1562630753.212 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-09T00:05:53.212Z,1562630753.212 [NAL9602] No Fault, FailCount= 2 2019-07-09T00:06:22.681Z,1562630782.681 [NAL9602](INFO): Powering up NAL9602 2019-07-09T00:06:33.574Z,1562630793.574 [NAL9602](INFO): NAL9602 initialized 2019-07-09T00:06:34.391Z,1562630794.391 [NAL9602](DEBUG): Fix Requested 2019-07-09T00:09:12.373Z,1562630952.373 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-09T00:09:12.373Z,1562630952.373 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19070817190424,35.0 0.0,1448.9, 0 2019-07-09T00:10:16.852Z,1562631016.852 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.195560 2019-07-09T00:10:26.634Z,1562631026.634 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.011127 2019-07-09T00:10:50.554Z,1562631050.554 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-09T00:05:50.4Z 2019-07-09T00:10:50.554Z,1562631050.554 [Default:CheckIn:Read_GPS] Stopped 2019-07-09T00:10:50.554Z,1562631050.554 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-09T00:10:59.247Z,1562631059.247 [DataOverHttps](INFO): Sending 224 bytes from file Logs/20190708T221730/Express0046.lzma 2019-07-09T00:11:00.053Z,1562631060.053 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0046.lzma.bak 2019-07-09T00:11:00.053Z,1562631060.053 [DataOverHttps](INFO): SBD MOMSN=11434102 2019-07-09T00:11:02.742Z,1562631062.742 [Default:CheckIn:Read_Iridium] Stopped 2019-07-09T00:11:02.742Z,1562631062.742 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-09T00:11:02.742Z,1562631062.742 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-09T00:11:37.385Z,1562631097.385 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-09T00:12:08.085Z,1562631128.085 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-09T00:16:03.261Z,1562631363.261 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-09T00:16:03.261Z,1562631363.261 [Default:CheckIn:C.Wait] Stopped 2019-07-09T00:16:03.261Z,1562631363.261 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-09T00:16:03.261Z,1562631363.261 [Default:CheckIn:D] Running Loop=1 2019-07-09T00:16:03.675Z,1562631363.675 [Default:CheckIn:D] Stopped 2019-07-09T00:16:03.675Z,1562631363.675 [Default:CheckIn:E] Running Loop=1 2019-07-09T00:16:04.048Z,1562631364.048 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 118.674870 min 2019-07-09T00:16:04.048Z,1562631364.048 [Default:CheckIn:E] Stopped 2019-07-09T00:16:04.048Z,1562631364.048 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-09T00:16:04.048Z,1562631364.048 [Default:CheckIn] Stopped 2019-07-09T00:16:04.048Z,1562631364.048 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-09T00:16:04.048Z,1562631364.048 [Default:CheckIn](INFO): Running loop #16 2019-07-09T00:16:04.048Z,1562631364.048 [Default:CheckIn] Running Loop=16 2019-07-09T00:16:04.049Z,1562631364.049 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-09T00:16:04.049Z,1562631364.049 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-09T00:16:05.667Z,1562631365.667 [NAL9602](DEBUG): Fix Requested 2019-07-09T00:16:23.029Z,1562631383.029 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-09T00:16:23.029Z,1562631383.029 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-07-09T00:16:36.765Z,1562631396.765 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-07-09T00:16:36.839Z,1562631396.839 [NAL9602](FAULT): received: +CSQ:0 OK99, 2, 0, 0, 0 OK 2019-07-09T00:16:36.839Z,1562631396.839 [NAL9602] Data Fault, FailCount= 3 2019-07-09T00:16:36.840Z,1562631396.840 [NAL9602](ERROR): Data Fault 2019-07-09T00:16:36.926Z,1562631396.926 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-09T00:16:37.169Z,1562631397.169 [NAL9602](INFO): Powering down 2019-07-09T00:16:38.049Z,1562631398.049 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-09T00:16:38.049Z,1562631398.049 [NAL9602] No Fault, FailCount= 3 2019-07-09T00:17:07.470Z,1562631427.470 [NAL9602](INFO): Powering up NAL9602 2019-07-09T00:17:18.383Z,1562631438.383 [NAL9602](INFO): NAL9602 initialized 2019-07-09T00:17:19.189Z,1562631439.189 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-07-09T00:17:19.189Z,1562631439.189 [NAL9602] Data Fault, FailCount= 4 2019-07-09T00:17:19.189Z,1562631439.189 [NAL9602](ERROR): Data Fault 2019-07-09T00:17:19.221Z,1562631439.221 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-09T00:17:19.597Z,1562631439.597 [NAL9602](INFO): Powering down 2019-07-09T00:17:20.433Z,1562631440.433 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-09T00:17:20.433Z,1562631440.433 [NAL9602] No Fault, FailCount= 4 2019-07-09T00:17:49.901Z,1562631469.901 [NAL9602](INFO): Powering up NAL9602 2019-07-09T00:18:00.801Z,1562631480.801 [NAL9602](INFO): NAL9602 initialized 2019-07-09T00:18:01.623Z,1562631481.623 [NAL9602](DEBUG): Fix Requested 2019-07-09T00:19:02.674Z,1562631542.674 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-07-09T00:19:02.674Z,1562631542.674 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-3268,-32768,V 2019-07-09T00:19:39.879Z,1562631579.879 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout 2019-07-09T00:19:39.879Z,1562631579.879 [RDI_Pathfinder] Communications Fault, FailCount= 1 2019-07-09T00:19:39.879Z,1562631579.879 [RDI_Pathfinder](ERROR): Communications Fault 2019-07-09T00:19:39.880Z,1562631579.880 [RDI_Pathfinder](ERROR): Failed to parse: 2019-07-09T00:19:39.903Z,1562631579.903 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder 2019-07-09T00:19:40.283Z,1562631580.283 [RDI_Pathfinder](INFO): Powering down 2019-07-09T00:19:41.024Z,1562631581.024 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder 2019-07-09T00:19:41.024Z,1562631581.024 [RDI_Pathfinder] No Fault, FailCount= 1 2019-07-09T00:19:54.366Z,1562631594.366 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder 2019-07-09T00:21:04.241Z,1562631664.241 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-09T00:16:04.0Z 2019-07-09T00:21:04.241Z,1562631664.241 [Default:CheckIn:Read_GPS] Stopped 2019-07-09T00:21:04.241Z,1562631664.241 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-09T00:21:07.849Z,1562631667.849 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-09T00:21:12.803Z,1562631672.803 [DataOverHttps](INFO): Sending 261 bytes from file Logs/20190708T221730/Express0049.lzma 2019-07-09T00:21:13.610Z,1562631673.610 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0049.lzma.bak 2019-07-09T00:21:13.610Z,1562631673.610 [DataOverHttps](INFO): SBD MOMSN=11434144 2019-07-09T00:21:15.962Z,1562631675.962 [Default:CheckIn:Read_Iridium] Stopped 2019-07-09T00:21:15.963Z,1562631675.963 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-09T00:21:15.963Z,1562631675.963 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-09T00:21:38.561Z,1562631698.561 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-09T00:26:16.549Z,1562631976.549 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-09T00:26:16.550Z,1562631976.550 [Default:CheckIn:C.Wait] Stopped 2019-07-09T00:26:16.550Z,1562631976.550 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-09T00:26:16.550Z,1562631976.550 [Default:CheckIn:D] Running Loop=1 2019-07-09T00:26:16.945Z,1562631976.945 [Default:CheckIn:D] Stopped 2019-07-09T00:26:16.945Z,1562631976.945 [Default:CheckIn:E] Running Loop=1 2019-07-09T00:26:17.358Z,1562631977.358 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 128.896037 min 2019-07-09T00:26:17.359Z,1562631977.359 [Default:CheckIn:E] Stopped 2019-07-09T00:26:17.359Z,1562631977.359 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-09T00:26:17.359Z,1562631977.359 [Default:CheckIn] Stopped 2019-07-09T00:26:17.359Z,1562631977.359 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-09T00:26:17.359Z,1562631977.359 [Default:CheckIn](INFO): Running loop #17 2019-07-09T00:26:17.359Z,1562631977.359 [Default:CheckIn] Running Loop=17 2019-07-09T00:26:17.360Z,1562631977.360 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-09T00:26:17.360Z,1562631977.360 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-09T00:26:18.955Z,1562631978.955 [NAL9602](DEBUG): Fix Requested 2019-07-09T00:28:00.388Z,1562632080.388 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-07-09T00:28:00.388Z,1562632080.388 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0.00, +0.00 +0.00, 0.00,485.99 2019-07-09T00:29:36.125Z,1562632176.125 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-07-09T00:29:36.128Z,1562632176.128 [BPC1](INFO): Received data from all battery sticks. 2019-07-09T00:31:17.531Z,1562632277.531 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-09T00:26:17.4Z 2019-07-09T00:31:17.531Z,1562632277.531 [Default:CheckIn:Read_GPS] Stopped 2019-07-09T00:31:17.532Z,1562632277.532 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-09T00:31:21.938Z,1562632281.938 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-09T00:31:32.183Z,1562632292.183 [DataOverHttps](INFO): Sending 45 bytes from file Logs/20190708T221730/Courier0051.lzma 2019-07-09T00:31:33.797Z,1562632293.797 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Courier0051.lzma.bak 2019-07-09T00:31:33.797Z,1562632293.797 [DataOverHttps](INFO): SBD MOMSN=11434150 2019-07-09T00:31:47.324Z,1562632307.324 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20190708T221730/Express0052.lzma 2019-07-09T00:31:49.117Z,1562632309.117 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0052.lzma.bak 2019-07-09T00:31:49.117Z,1562632309.117 [DataOverHttps](INFO): SBD MOMSN=11434152 2019-07-09T00:31:51.488Z,1562632311.488 [Default:CheckIn:Read_Iridium] Stopped 2019-07-09T00:31:51.488Z,1562632311.488 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-09T00:31:51.488Z,1562632311.488 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-09T00:31:51.853Z,1562632311.853 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-09T00:31:51.853Z,1562632311.853 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-07-09T00:31:52.670Z,1562632312.670 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-09T00:35:16.302Z,1562632516.302 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-09T00:35:16.302Z,1562632516.302 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-07-09T00:36:52.038Z,1562632612.038 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-09T00:36:52.038Z,1562632612.038 [Default:CheckIn:C.Wait] Stopped 2019-07-09T00:36:52.038Z,1562632612.038 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-09T00:36:52.039Z,1562632612.039 [Default:CheckIn:D] Running Loop=1 2019-07-09T00:36:52.442Z,1562632612.442 [Default:CheckIn:D] Stopped 2019-07-09T00:36:52.442Z,1562632612.442 [Default:CheckIn:E] Running Loop=1 2019-07-09T00:36:52.854Z,1562632612.854 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 139.487663 min 2019-07-09T00:36:52.854Z,1562632612.854 [Default:CheckIn:E] Stopped 2019-07-09T00:36:52.854Z,1562632612.854 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-09T00:36:52.854Z,1562632612.854 [Default:CheckIn] Stopped 2019-07-09T00:36:52.854Z,1562632612.854 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-09T00:36:52.855Z,1562632612.855 [Default:CheckIn](INFO): Running loop #18 2019-07-09T00:36:52.855Z,1562632612.855 [Default:CheckIn] Running Loop=18 2019-07-09T00:36:52.855Z,1562632612.855 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-09T00:36:52.855Z,1562632612.855 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-09T00:36:54.433Z,1562632614.433 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-07-09T00:36:54.433Z,1562632614.433 [NAL9602] Data Fault, FailCount= 5 2019-07-09T00:36:54.433Z,1562632614.433 [NAL9602](ERROR): Data Fault 2019-07-09T00:36:54.492Z,1562632614.492 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-09T00:36:54.493Z,1562632614.493 [CBIT](CRITICAL): Data Fault in component: NAL9602 2019-07-09T00:36:54.833Z,1562632614.833 [NAL9602](INFO): Powering down 2019-07-09T00:36:54.869Z,1562632614.869 [CBIT](INFO): Critical error at 20190709T003654 2019-07-09T00:37:39.705Z,1562632659.705 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-09T00:37:39.705Z,1562632659.705 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-07-09T00:38:54.470Z,1562632734.470 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-09T00:38:54.470Z,1562632734.470 [NAL9602] No Fault, FailCount= 5 2019-07-09T00:38:54.822Z,1562632734.822 [NAL9602](INFO): Powering up NAL9602 2019-07-09T00:39:05.729Z,1562632745.729 [NAL9602](INFO): NAL9602 initialized 2019-07-09T00:39:06.563Z,1562632746.563 [NAL9602](DEBUG): Fix Requested 2019-07-09T00:41:53.039Z,1562632913.039 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-09T00:36:52.9Z 2019-07-09T00:41:53.039Z,1562632913.039 [Default:CheckIn:Read_GPS] Stopped 2019-07-09T00:41:53.039Z,1562632913.039 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-09T00:42:08.095Z,1562632928.095 [DataOverHttps](INFO): Sending 69 bytes from file Logs/20190708T221730/Courier0054.lzma 2019-07-09T00:42:08.901Z,1562632928.901 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Courier0054.lzma.bak 2019-07-09T00:42:08.901Z,1562632928.901 [DataOverHttps](INFO): SBD MOMSN=11434156 2019-07-09T00:42:31.763Z,1562632951.763 [DataOverHttps](INFO): Sending 229 bytes from file Logs/20190708T221730/Express0055.lzma 2019-07-09T00:42:32.569Z,1562632952.569 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0055.lzma.bak 2019-07-09T00:42:32.569Z,1562632952.569 [DataOverHttps](INFO): SBD MOMSN=11434159 2019-07-09T00:42:35.120Z,1562632955.120 [Default:CheckIn:Read_Iridium] Stopped 2019-07-09T00:42:35.120Z,1562632955.120 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-09T00:42:35.120Z,1562632955.120 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-09T00:44:09.193Z,1562633049.193 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-09T00:44:39.897Z,1562633079.897 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-09T00:47:35.677Z,1562633255.677 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-09T00:47:35.677Z,1562633255.677 [Default:CheckIn:C.Wait] Stopped 2019-07-09T00:47:35.677Z,1562633255.677 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-09T00:47:35.678Z,1562633255.678 [Default:CheckIn:D] Running Loop=1 2019-07-09T00:47:36.076Z,1562633256.076 [Default:CheckIn:D] Stopped 2019-07-09T00:47:36.076Z,1562633256.076 [Default:CheckIn:E] Running Loop=1 2019-07-09T00:47:36.474Z,1562633256.474 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 150.214893 min 2019-07-09T00:47:36.474Z,1562633256.474 [Default:CheckIn:E] Stopped 2019-07-09T00:47:36.474Z,1562633256.474 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-09T00:47:36.474Z,1562633256.474 [Default:CheckIn] Stopped 2019-07-09T00:47:36.474Z,1562633256.474 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-09T00:47:36.475Z,1562633256.475 [Default:CheckIn](INFO): Running loop #19 2019-07-09T00:47:36.475Z,1562633256.475 [Default:CheckIn] Running Loop=19 2019-07-09T00:47:36.475Z,1562633256.475 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-09T00:47:36.491Z,1562633256.491 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-09T00:47:38.071Z,1562633258.071 [NAL9602](DEBUG): Fix Requested 2019-07-09T00:48:33.843Z,1562633313.843 [RDI_Pathfinder](ERROR): Failed to parse: :SA, +0.00, +0.00, 0.00 2019-07-09T00:49:53.023Z,1562633393.023 [RDI_Pathfinder](ERROR): Failed to parse: :BI,-32768,-32768,-32768,-32768,V 2019-07-09T00:51:34.017Z,1562633494.017 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-09T00:51:34.017Z,1562633494.017 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-07-09T00:52:36.650Z,1562633556.650 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-09T00:47:36.5Z 2019-07-09T00:52:36.650Z,1562633556.650 [Default:CheckIn:Read_GPS] Stopped 2019-07-09T00:52:36.651Z,1562633556.651 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-09T00:52:40.261Z,1562633560.261 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-09T00:52:43.703Z,1562633563.703 [DataOverHttps](INFO): Sending 210 bytes from file Logs/20190708T221730/Express0058.lzma 2019-07-09T00:52:44.509Z,1562633564.509 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0058.lzma.bak 2019-07-09T00:52:44.509Z,1562633564.509 [DataOverHttps](INFO): SBD MOMSN=11434164 2019-07-09T00:52:47.154Z,1562633567.154 [Default:CheckIn:Read_Iridium] Stopped 2019-07-09T00:52:47.155Z,1562633567.155 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-09T00:52:47.155Z,1562633567.155 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-09T00:53:10.953Z,1562633590.953 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-09T00:57:47.718Z,1562633867.718 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-09T00:57:47.718Z,1562633867.718 [Default:CheckIn:C.Wait] Stopped 2019-07-09T00:57:47.718Z,1562633867.718 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-09T00:57:47.719Z,1562633867.719 [Default:CheckIn:D] Running Loop=1 2019-07-09T00:57:48.130Z,1562633868.130 [Default:CheckIn:D] Stopped 2019-07-09T00:57:48.130Z,1562633868.130 [Default:CheckIn:E] Running Loop=1 2019-07-09T00:57:48.573Z,1562633868.573 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 160.415788 min 2019-07-09T00:57:48.574Z,1562633868.574 [Default:CheckIn:E] Stopped 2019-07-09T00:57:48.574Z,1562633868.574 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-09T00:57:48.574Z,1562633868.574 [Default:CheckIn] Stopped 2019-07-09T00:57:48.574Z,1562633868.574 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-09T00:57:48.574Z,1562633868.574 [Default:CheckIn](INFO): Running loop #20 2019-07-09T00:57:48.574Z,1562633868.574 [Default:CheckIn] Running Loop=20 2019-07-09T00:57:48.574Z,1562633868.574 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-09T00:57:48.574Z,1562633868.574 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-09T00:57:50.123Z,1562633870.123 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-07-09T00:57:50.123Z,1562633870.123 [NAL9602] Data Fault, FailCount= 1 2019-07-09T00:57:50.123Z,1562633870.123 [NAL9602](ERROR): Data Fault 2019-07-09T00:57:50.163Z,1562633870.163 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-09T00:57:50.525Z,1562633870.525 [NAL9602](INFO): Powering down 2019-07-09T00:57:51.380Z,1562633871.380 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-09T00:57:51.380Z,1562633871.380 [NAL9602] No Fault, FailCount= 1 2019-07-09T00:58:20.821Z,1562633900.821 [NAL9602](INFO): Powering up NAL9602 2019-07-09T00:58:31.731Z,1562633911.731 [NAL9602](INFO): NAL9602 initialized 2019-07-09T00:58:32.555Z,1562633912.555 [NAL9602](DEBUG): Fix Requested 2019-07-09T00:58:44.676Z,1562633924.676 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-09T00:58:44.676Z,1562633924.676 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19070818083691,35.0, -0.1, 0.0,1448.9A, 0.00, 0.00, 0.00, 0.00, 0.00 2019-07-09T00:59:21.475Z,1562633961.475 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-07-09T00:59:30.359Z,1562633970.359 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-07-09T00:59:30.359Z,1562633970.359 [RDI_Pathfinder](ERROR): Failed to parse: :BD +0.00, +0.00, +0.00, 0.00,2375.75 2019-07-09T01:02:48.726Z,1562634168.726 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-09T00:57:48.6Z 2019-07-09T01:02:48.727Z,1562634168.727 [Default:CheckIn:Read_GPS] Stopped 2019-07-09T01:02:48.727Z,1562634168.727 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-09T01:02:56.567Z,1562634176.567 [DataOverHttps](INFO): Sending 224 bytes from file Logs/20190708T221730/Express0061.lzma 2019-07-09T01:02:57.373Z,1562634177.373 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0061.lzma.bak 2019-07-09T01:02:57.373Z,1562634177.373 [DataOverHttps](INFO): SBD MOMSN=11434168 2019-07-09T01:02:59.678Z,1562634179.678 [Default:CheckIn:Read_Iridium] Stopped 2019-07-09T01:02:59.678Z,1562634179.678 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-09T01:02:59.678Z,1562634179.678 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-09T01:03:35.145Z,1562634215.145 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-09T01:04:05.853Z,1562634245.853 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-09T01:08:00.218Z,1562634480.218 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-09T01:08:00.218Z,1562634480.218 [Default:CheckIn:C.Wait] Stopped 2019-07-09T01:08:00.218Z,1562634480.218 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-09T01:08:00.218Z,1562634480.218 [Default:CheckIn:D] Running Loop=1 2019-07-09T01:08:00.614Z,1562634480.614 [Default:CheckIn:D] Stopped 2019-07-09T01:08:00.614Z,1562634480.614 [Default:CheckIn:E] Running Loop=1 2019-07-09T01:08:01.003Z,1562634481.003 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 170.623861 min 2019-07-09T01:08:01.003Z,1562634481.003 [Default:CheckIn:E] Stopped 2019-07-09T01:08:01.003Z,1562634481.003 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-09T01:08:01.003Z,1562634481.003 [Default:CheckIn] Stopped 2019-07-09T01:08:01.003Z,1562634481.003 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-09T01:08:01.003Z,1562634481.003 [Default:CheckIn](INFO): Running loop #21 2019-07-09T01:08:01.004Z,1562634481.004 [Default:CheckIn] Running Loop=21 2019-07-09T01:08:01.004Z,1562634481.004 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-09T01:08:01.004Z,1562634481.004 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-09T01:08:02.623Z,1562634482.623 [NAL9602](DEBUG): Fix Requested 2019-07-09T01:08:02.651Z,1562634482.651 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-07-09T01:08:02.652Z,1562634482.652 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0.00, , +0.00, 0.00,2887.63 2019-07-09T01:08:33.705Z,1562634513.705 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-07-09T01:08:33.783Z,1562634513.783 [NAL9602](FAULT): received: +CSQ:0 OK99, 2, 0, 0, 0 OK 2019-07-09T01:08:33.784Z,1562634513.784 [NAL9602] Data Fault, FailCount= 2 2019-07-09T01:08:33.784Z,1562634513.784 [NAL9602](ERROR): Data Fault 2019-07-09T01:08:33.861Z,1562634513.861 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-09T01:08:34.105Z,1562634514.105 [NAL9602](INFO): Powering down 2019-07-09T01:08:34.959Z,1562634514.959 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-09T01:08:34.959Z,1562634514.959 [NAL9602] No Fault, FailCount= 2 2019-07-09T01:09:04.406Z,1562634544.406 [NAL9602](INFO): Powering up NAL9602 2019-07-09T01:09:15.311Z,1562634555.311 [NAL9602](INFO): NAL9602 initialized 2019-07-09T01:09:16.125Z,1562634556.125 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-07-09T01:09:16.125Z,1562634556.125 [NAL9602] Data Fault, FailCount= 3 2019-07-09T01:09:16.125Z,1562634556.125 [NAL9602](ERROR): Data Fault 2019-07-09T01:09:16.162Z,1562634556.162 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-09T01:09:16.525Z,1562634556.525 [NAL9602](INFO): Powering down 2019-07-09T01:09:17.392Z,1562634557.392 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-09T01:09:17.392Z,1562634557.392 [NAL9602] No Fault, FailCount= 3 2019-07-09T01:09:46.825Z,1562634586.825 [NAL9602](INFO): Powering up NAL9602 2019-07-09T01:09:57.734Z,1562634597.734 [NAL9602](INFO): NAL9602 initialized 2019-07-09T01:09:58.559Z,1562634598.559 [NAL9602](DEBUG): Fix Requested 2019-07-09T01:10:27.279Z,1562634627.279 [RDI_Pathfinder](ERROR): Failed to parse: 68,-32768,-32768,V 2019-07-09T01:13:01.172Z,1562634781.172 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-09T01:08:01.0Z 2019-07-09T01:13:01.172Z,1562634781.172 [Default:CheckIn:Read_GPS] Stopped 2019-07-09T01:13:01.172Z,1562634781.172 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-09T01:13:04.785Z,1562634784.785 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-09T01:13:12.595Z,1562634792.595 [DataOverHttps](INFO): Sending 263 bytes from file Logs/20190708T221730/Express0064.lzma 2019-07-09T01:13:13.409Z,1562634793.409 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0064.lzma.bak 2019-07-09T01:13:13.409Z,1562634793.409 [DataOverHttps](INFO): SBD MOMSN=11434173 2019-07-09T01:13:16.134Z,1562634796.134 [Default:CheckIn:Read_Iridium] Stopped 2019-07-09T01:13:16.134Z,1562634796.134 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-09T01:13:16.134Z,1562634796.134 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-09T01:13:35.487Z,1562634815.487 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-09T01:16:14.306Z,1562634974.306 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-07-09T01:16:14.306Z,1562634974.306 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0. +0.00, +0.00, 0.00,3379.51 2019-07-09T01:18:16.706Z,1562635096.706 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-09T01:18:16.706Z,1562635096.706 [Default:CheckIn:C.Wait] Stopped 2019-07-09T01:18:16.706Z,1562635096.706 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-09T01:18:16.707Z,1562635096.707 [Default:CheckIn:D] Running Loop=1 2019-07-09T01:18:17.106Z,1562635097.106 [Default:CheckIn:D] Stopped 2019-07-09T01:18:17.106Z,1562635097.106 [Default:CheckIn:E] Running Loop=1 2019-07-09T01:18:17.515Z,1562635097.515 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 180.898730 min 2019-07-09T01:18:17.515Z,1562635097.515 [Default:CheckIn:E] Stopped 2019-07-09T01:18:17.516Z,1562635097.516 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-09T01:18:17.516Z,1562635097.516 [Default:CheckIn] Stopped 2019-07-09T01:18:17.516Z,1562635097.516 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-09T01:18:17.516Z,1562635097.516 [Default:CheckIn](INFO): Running loop #22 2019-07-09T01:18:17.516Z,1562635097.516 [Default:CheckIn] Running Loop=22 2019-07-09T01:18:17.516Z,1562635097.516 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-09T01:18:17.516Z,1562635097.516 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-09T01:18:19.115Z,1562635099.115 [NAL9602](DEBUG): Fix Requested 2019-07-09T01:20:54.659Z,1562635254.659 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-09T01:20:54.659Z,1562635254.659 [RDI_Pathfinder](ERROR): Failed to parse: :TS8304691,35.0, -0.1, 0.0,1448.9, 0 2019-07-09T01:22:20.722Z,1562635340.722 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-09T01:22:20.723Z,1562635340.723 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19070818321291,.1, 0.0,1448.9, 0 2019-07-09T01:23:17.680Z,1562635397.680 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-09T01:18:17.5Z 2019-07-09T01:23:17.680Z,1562635397.680 [Default:CheckIn:Read_GPS] Stopped 2019-07-09T01:23:17.681Z,1562635397.681 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-09T01:23:21.287Z,1562635401.287 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-09T01:23:26.443Z,1562635406.443 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20190708T221730/Express0067.lzma 2019-07-09T01:23:27.253Z,1562635407.253 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0067.lzma.bak 2019-07-09T01:23:27.254Z,1562635407.254 [DataOverHttps](INFO): SBD MOMSN=11434179 2019-07-09T01:23:31.039Z,1562635411.039 [Default:CheckIn:Read_Iridium] Stopped 2019-07-09T01:23:31.039Z,1562635411.039 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-09T01:23:31.039Z,1562635411.039 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-09T01:23:51.994Z,1562635431.994 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-09T01:25:17.291Z,1562635517.291 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-07-09T01:25:17.291Z,1562635517.291 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0.00, +0.00, , 0.00,3922.38 2019-07-09T01:28:31.601Z,1562635711.601 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-09T01:28:31.601Z,1562635711.601 [Default:CheckIn:C.Wait] Stopped 2019-07-09T01:28:31.601Z,1562635711.601 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-09T01:28:31.601Z,1562635711.601 [Default:CheckIn:D] Running Loop=1 2019-07-09T01:28:32.002Z,1562635712.002 [Default:CheckIn:D] Stopped 2019-07-09T01:28:32.002Z,1562635712.002 [Default:CheckIn:E] Running Loop=1 2019-07-09T01:28:32.410Z,1562635712.410 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 191.147005 min 2019-07-09T01:28:32.410Z,1562635712.410 [Default:CheckIn:E] Stopped 2019-07-09T01:28:32.410Z,1562635712.410 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-09T01:28:32.410Z,1562635712.410 [Default:CheckIn] Stopped 2019-07-09T01:28:32.411Z,1562635712.411 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-09T01:28:32.411Z,1562635712.411 [Default:CheckIn](INFO): Running loop #23 2019-07-09T01:28:32.411Z,1562635712.411 [Default:CheckIn] Running Loop=23 2019-07-09T01:28:32.411Z,1562635712.411 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-09T01:28:32.411Z,1562635712.411 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-09T01:28:33.990Z,1562635713.990 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-07-09T01:28:33.990Z,1562635713.990 [NAL9602] Data Fault, FailCount= 4 2019-07-09T01:28:33.990Z,1562635713.990 [NAL9602](ERROR): Data Fault 2019-07-09T01:28:34.036Z,1562635714.036 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-09T01:28:34.389Z,1562635714.389 [NAL9602](INFO): Powering down 2019-07-09T01:28:35.268Z,1562635715.268 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-09T01:28:35.268Z,1562635715.268 [NAL9602] No Fault, FailCount= 4 2019-07-09T01:29:04.689Z,1562635744.689 [NAL9602](INFO): Powering up NAL9602 2019-07-09T01:29:15.597Z,1562635755.597 [NAL9602](INFO): NAL9602 initialized 2019-07-09T01:29:16.419Z,1562635756.419 [NAL9602](DEBUG): Fix Requested 2019-07-09T01:29:33.795Z,1562635773.795 [RDI_Pathfinder](ERROR): Failed to parse: :SA, +0.00, +0.00, 0.00 2019-07-09T01:31:33.815Z,1562635893.815 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-07-09T01:31:33.815Z,1562635893.815 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.0023 2019-07-09T01:33:32.620Z,1562636012.620 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-09T01:28:32.4Z 2019-07-09T01:33:32.621Z,1562636012.621 [Default:CheckIn:Read_GPS] Stopped 2019-07-09T01:33:32.621Z,1562636012.621 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-09T01:33:40.029Z,1562636020.029 [DataOverHttps](INFO): Sending 227 bytes from file Logs/20190708T221730/Express0070.lzma 2019-07-09T01:33:40.833Z,1562636020.833 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0070.lzma.bak 2019-07-09T01:33:40.833Z,1562636020.833 [DataOverHttps](INFO): SBD MOMSN=11434183 2019-07-09T01:33:43.490Z,1562636023.490 [Default:CheckIn:Read_Iridium] Stopped 2019-07-09T01:33:43.490Z,1562636023.490 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-09T01:33:43.490Z,1562636023.490 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-09T01:34:19.021Z,1562636059.021 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-09T01:34:49.721Z,1562636089.721 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-09T01:37:00.247Z,1562636220.247 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-07-09T01:37:00.250Z,1562636220.250 [BPC1](INFO): Received data from all battery sticks. 2019-07-09T01:38:44.091Z,1562636324.091 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-09T01:38:44.091Z,1562636324.091 [Default:CheckIn:C.Wait] Stopped 2019-07-09T01:38:44.091Z,1562636324.091 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-09T01:38:44.092Z,1562636324.092 [Default:CheckIn:D] Running Loop=1 2019-07-09T01:38:44.521Z,1562636324.521 [Default:CheckIn:D] Stopped 2019-07-09T01:38:44.521Z,1562636324.521 [Default:CheckIn:E] Running Loop=1 2019-07-09T01:38:44.891Z,1562636324.891 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 201.355632 min 2019-07-09T01:38:44.891Z,1562636324.891 [Default:CheckIn:E] Stopped 2019-07-09T01:38:44.891Z,1562636324.891 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-09T01:38:44.891Z,1562636324.891 [Default:CheckIn] Stopped 2019-07-09T01:38:44.891Z,1562636324.891 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-09T01:38:44.891Z,1562636324.891 [Default:CheckIn](INFO): Running loop #24 2019-07-09T01:38:44.892Z,1562636324.892 [Default:CheckIn] Running Loop=24 2019-07-09T01:38:44.892Z,1562636324.892 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-09T01:38:44.892Z,1562636324.892 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-09T01:38:46.495Z,1562636326.495 [NAL9602](DEBUG): Fix Requested 2019-07-09T01:39:17.594Z,1562636357.594 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-07-09T01:39:17.671Z,1562636357.671 [NAL9602](FAULT): received: +CSQ:0 OK99, 2, 0, 0, 0 OK 2019-07-09T01:39:17.671Z,1562636357.671 [NAL9602] Data Fault, FailCount= 5 2019-07-09T01:39:17.671Z,1562636357.671 [NAL9602](ERROR): Data Fault 2019-07-09T01:39:17.714Z,1562636357.714 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-09T01:39:17.714Z,1562636357.714 [CBIT](CRITICAL): Data Fault in component: NAL9602 2019-07-09T01:39:18.021Z,1562636358.021 [NAL9602](INFO): Powering down 2019-07-09T01:39:18.061Z,1562636358.061 [CBIT](INFO): Critical error at 20190709T013917 2019-07-09T01:39:18.394Z,1562636358.394 [NAL9602](FAULT): LCB fault: LCB Watchdog Reset. Invalid Command. 2019-07-09T01:39:18.394Z,1562636358.394 [NAL9602] Hardware Fault, FailCount= 5 2019-07-09T01:39:18.394Z,1562636358.394 [NAL9602](ERROR): Hardware Fault 2019-07-09T01:41:18.030Z,1562636478.030 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-09T01:41:18.030Z,1562636478.030 [NAL9602] No Fault, FailCount= 5 2019-07-09T01:41:18.413Z,1562636478.413 [NAL9602](INFO): Powering up NAL9602 2019-07-09T01:41:29.299Z,1562636489.299 [NAL9602](INFO): NAL9602 initialized 2019-07-09T01:41:30.109Z,1562636490.109 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-07-09T01:41:30.109Z,1562636490.109 [NAL9602] Data Fault, FailCount= 1 2019-07-09T01:41:30.109Z,1562636490.109 [NAL9602](ERROR): Data Fault 2019-07-09T01:41:30.167Z,1562636490.167 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-09T01:41:30.511Z,1562636490.511 [NAL9602](INFO): Powering down 2019-07-09T01:41:31.372Z,1562636491.372 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-09T01:41:31.372Z,1562636491.372 [NAL9602] No Fault, FailCount= 1 2019-07-09T01:42:00.803Z,1562636520.803 [NAL9602](INFO): Powering up NAL9602 2019-07-09T01:42:11.711Z,1562636531.711 [NAL9602](INFO): NAL9602 initialized 2019-07-09T01:42:12.531Z,1562636532.531 [NAL9602](DEBUG): Fix Requested 2019-07-09T01:43:45.122Z,1562636625.122 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-09T01:38:44.9Z 2019-07-09T01:43:45.123Z,1562636625.123 [Default:CheckIn:Read_GPS] Stopped 2019-07-09T01:43:45.123Z,1562636625.123 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-09T01:43:49.117Z,1562636629.117 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-09T01:43:54.976Z,1562636634.976 [DataOverHttps](INFO): Sending 87 bytes from file Logs/20190708T221730/Courier0072.lzma 2019-07-09T01:43:55.781Z,1562636635.781 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Courier0072.lzma.bak 2019-07-09T01:43:55.781Z,1562636635.781 [DataOverHttps](INFO): SBD MOMSN=11434188 2019-07-09T01:44:19.777Z,1562636659.777 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-09T01:44:27.616Z,1562636667.616 [DataOverHttps](INFO): Sending 304 bytes from file Logs/20190708T221730/Express0073.lzma 2019-07-09T01:44:28.421Z,1562636668.421 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0073.lzma.bak 2019-07-09T01:44:28.421Z,1562636668.421 [DataOverHttps](INFO): SBD MOMSN=11434191 2019-07-09T01:44:30.722Z,1562636670.722 [Default:CheckIn:Read_Iridium] Stopped 2019-07-09T01:44:30.723Z,1562636670.723 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-09T01:44:30.723Z,1562636670.723 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-09T01:49:31.286Z,1562636971.286 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-09T01:49:31.286Z,1562636971.286 [Default:CheckIn:C.Wait] Stopped 2019-07-09T01:49:31.286Z,1562636971.286 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-09T01:49:31.286Z,1562636971.286 [Default:CheckIn:D] Running Loop=1 2019-07-09T01:49:31.704Z,1562636971.704 [Default:CheckIn:D] Stopped 2019-07-09T01:49:31.704Z,1562636971.704 [Default:CheckIn:E] Running Loop=1 2019-07-09T01:49:32.107Z,1562636972.107 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 212.142025 min 2019-07-09T01:49:32.107Z,1562636972.107 [Default:CheckIn:E] Stopped 2019-07-09T01:49:32.107Z,1562636972.107 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-09T01:49:32.107Z,1562636972.107 [Default:CheckIn] Stopped 2019-07-09T01:49:32.112Z,1562636972.112 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-09T01:49:32.112Z,1562636972.112 [Default:CheckIn](INFO): Running loop #25 2019-07-09T01:49:32.112Z,1562636972.112 [Default:CheckIn] Running Loop=25 2019-07-09T01:49:32.112Z,1562636972.112 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-09T01:49:32.112Z,1562636972.112 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-09T01:49:33.703Z,1562636973.703 [NAL9602](DEBUG): Fix Requested 2019-07-09T01:50:04.799Z,1562637004.799 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-07-09T01:50:04.871Z,1562637004.871 [NAL9602](FAULT): received: +CSQ:0 OK99, 2, 0, 0, 0 OK 2019-07-09T01:50:04.871Z,1562637004.871 [NAL9602] Data Fault, FailCount= 2 2019-07-09T01:50:04.871Z,1562637004.871 [NAL9602](ERROR): Data Fault 2019-07-09T01:50:04.940Z,1562637004.940 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-09T01:50:05.197Z,1562637005.197 [NAL9602](INFO): Powering down 2019-07-09T01:50:06.063Z,1562637006.063 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-09T01:50:06.067Z,1562637006.067 [NAL9602] No Fault, FailCount= 2 2019-07-09T01:50:35.501Z,1562637035.501 [NAL9602](INFO): Powering up NAL9602 2019-07-09T01:50:46.409Z,1562637046.409 [NAL9602](INFO): NAL9602 initialized 2019-07-09T01:50:47.252Z,1562637047.252 [NAL9602](DEBUG): Fix Requested 2019-07-09T01:53:06.257Z,1562637186.257 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-07-09T01:53:06.257Z,1562637186.257 [RDI_Pathfinder](ERROR): Failed to parse: :BS,32768,-32768,V 2019-07-09T01:53:25.624Z,1562637205.624 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-09T01:53:25.624Z,1562637205.624 [RDI_Pathfinder](ERROR): Failed to parse: :TS,190708195.0, -0.1, 0.0,1448.9, 0 2019-07-09T01:54:32.311Z,1562637272.311 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-09T01:49:32.1Z 2019-07-09T01:54:32.311Z,1562637272.311 [Default:CheckIn:Read_GPS] Stopped 2019-07-09T01:54:32.311Z,1562637272.311 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-09T01:54:36.021Z,1562637276.021 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-09T01:54:36.394Z,1562637276.394 [DataOverHttps](INFO): Sending 249 bytes from file Logs/20190708T221730/Express0076.lzma 2019-07-09T01:54:37.205Z,1562637277.205 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0076.lzma.bak 2019-07-09T01:54:37.205Z,1562637277.205 [DataOverHttps](INFO): SBD MOMSN=11434198 2019-07-09T01:54:40.095Z,1562637280.095 [Default:CheckIn:Read_Iridium] Stopped 2019-07-09T01:54:40.095Z,1562637280.095 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-09T01:54:40.095Z,1562637280.095 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-09T01:55:06.725Z,1562637306.725 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-09T01:56:56.262Z,1562637416.262 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-07-09T01:59:40.674Z,1562637580.674 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-09T01:59:40.674Z,1562637580.674 [Default:CheckIn:C.Wait] Stopped 2019-07-09T01:59:40.674Z,1562637580.674 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-09T01:59:40.675Z,1562637580.675 [Default:CheckIn:D] Running Loop=1 2019-07-09T01:59:41.070Z,1562637581.070 [Default:CheckIn:D] Stopped 2019-07-09T01:59:41.070Z,1562637581.070 [Default:CheckIn:E] Running Loop=1 2019-07-09T01:59:41.486Z,1562637581.486 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 222.298128 min 2019-07-09T01:59:41.487Z,1562637581.487 [Default:CheckIn:E] Stopped 2019-07-09T01:59:41.487Z,1562637581.487 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-09T01:59:41.487Z,1562637581.487 [Default:CheckIn] Stopped 2019-07-09T01:59:41.487Z,1562637581.487 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-09T01:59:41.487Z,1562637581.487 [Default:CheckIn](INFO): Running loop #26 2019-07-09T01:59:41.487Z,1562637581.487 [Default:CheckIn] Running Loop=26 2019-07-09T01:59:41.488Z,1562637581.488 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-09T01:59:41.488Z,1562637581.488 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-09T01:59:43.061Z,1562637583.061 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-07-09T01:59:43.061Z,1562637583.061 [NAL9602] Data Fault, FailCount= 3 2019-07-09T01:59:43.062Z,1562637583.062 [NAL9602](ERROR): Data Fault 2019-07-09T01:59:43.135Z,1562637583.135 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-09T01:59:43.465Z,1562637583.465 [NAL9602](INFO): Powering down 2019-07-09T01:59:44.367Z,1562637584.367 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-09T01:59:44.368Z,1562637584.368 [NAL9602] No Fault, FailCount= 3 2019-07-09T01:59:59.646Z,1562637599.646 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-07-09T02:00:13.765Z,1562637613.765 [NAL9602](INFO): Powering up NAL9602 2019-07-09T02:00:24.673Z,1562637624.673 [NAL9602](INFO): NAL9602 initialized 2019-07-09T02:00:25.499Z,1562637625.499 [NAL9602](DEBUG): Fix Requested 2019-07-09T02:01:14.006Z,1562637674.006 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-07-09T02:01:14.006Z,1562637674.006 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-3276,-32768,V 2019-07-09T02:02:39.650Z,1562637759.650 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-09T02:02:39.650Z,1562637759.650 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-07-09T02:04:41.662Z,1562637881.662 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-09T01:59:41.5Z 2019-07-09T02:04:41.662Z,1562637881.662 [Default:CheckIn:Read_GPS] Stopped 2019-07-09T02:04:41.662Z,1562637881.662 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-09T02:04:50.175Z,1562637890.175 [DataOverHttps](INFO): Sending 224 bytes from file Logs/20190708T221730/Express0079.lzma 2019-07-09T02:04:50.981Z,1562637890.981 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0079.lzma.bak 2019-07-09T02:04:50.981Z,1562637890.981 [DataOverHttps](INFO): SBD MOMSN=11434238 2019-07-09T02:04:53.779Z,1562637893.779 [Default:CheckIn:Read_Iridium] Stopped 2019-07-09T02:04:53.779Z,1562637893.779 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-09T02:04:53.779Z,1562637893.779 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-09T02:05:28.085Z,1562637928.085 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-09T02:05:58.789Z,1562637958.789 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-09T02:09:54.371Z,1562638194.371 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-09T02:09:54.371Z,1562638194.371 [Default:CheckIn:C.Wait] Stopped 2019-07-09T02:09:54.371Z,1562638194.371 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-09T02:09:54.375Z,1562638194.375 [Default:CheckIn:D] Running Loop=1 2019-07-09T02:09:54.746Z,1562638194.746 [Default:CheckIn:D] Stopped 2019-07-09T02:09:54.746Z,1562638194.746 [Default:CheckIn:E] Running Loop=1 2019-07-09T02:09:55.151Z,1562638195.151 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 232.526058 min 2019-07-09T02:09:55.151Z,1562638195.151 [Default:CheckIn:E] Stopped 2019-07-09T02:09:55.151Z,1562638195.151 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-09T02:09:55.151Z,1562638195.151 [Default:CheckIn] Stopped 2019-07-09T02:09:55.151Z,1562638195.151 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-09T02:09:55.151Z,1562638195.151 [Default:CheckIn](INFO): Running loop #27 2019-07-09T02:09:55.152Z,1562638195.152 [Default:CheckIn] Running Loop=27 2019-07-09T02:09:55.152Z,1562638195.152 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-09T02:09:55.152Z,1562638195.152 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-09T02:09:56.755Z,1562638196.755 [NAL9602](DEBUG): Fix Requested 2019-07-09T02:13:41.820Z,1562638421.820 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-07-09T02:14:55.345Z,1562638495.345 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-09T02:09:55.2Z 2019-07-09T02:14:55.345Z,1562638495.345 [Default:CheckIn:Read_GPS] Stopped 2019-07-09T02:14:55.345Z,1562638495.345 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-09T02:14:58.937Z,1562638498.937 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-09T02:15:07.484Z,1562638507.484 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20190708T221730/Express0082.lzma 2019-07-09T02:15:08.289Z,1562638508.289 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0082.lzma.bak 2019-07-09T02:15:08.289Z,1562638508.289 [DataOverHttps](INFO): SBD MOMSN=11434243 2019-07-09T02:15:10.746Z,1562638510.746 [Default:CheckIn:Read_Iridium] Stopped 2019-07-09T02:15:10.746Z,1562638510.746 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-09T02:15:10.746Z,1562638510.746 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-09T02:15:29.653Z,1562638529.653 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-09T02:17:03.806Z,1562638623.806 [RDI_Pathfinder](ERROR): only read 1 of 4 data items 2019-07-09T02:17:03.806Z,1562638623.806 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768-32768,V 2019-07-09T02:20:03.978Z,1562638803.978 [RDI_Pathfinder](ERROR): only read 0 of 4 data items 2019-07-09T02:20:03.978Z,1562638803.978 [RDI_Pathfinder](ERROR): Failed to parse: :BS-32768,-32768,V 2019-07-09T02:20:09.627Z,1562638809.627 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-09T02:20:09.627Z,1562638809.627 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19070819300191,35.0, -0.1, 0.0,14 2019-07-09T02:20:11.260Z,1562638811.260 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-09T02:20:11.260Z,1562638811.260 [Default:CheckIn:C.Wait] Stopped 2019-07-09T02:20:11.260Z,1562638811.260 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-09T02:20:11.260Z,1562638811.260 [Default:CheckIn:D] Running Loop=1 2019-07-09T02:20:11.683Z,1562638811.683 [Default:CheckIn:D] Stopped 2019-07-09T02:20:11.683Z,1562638811.683 [Default:CheckIn:E] Running Loop=1 2019-07-09T02:20:12.059Z,1562638812.059 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 242.808333 min 2019-07-09T02:20:12.059Z,1562638812.059 [Default:CheckIn:E] Stopped 2019-07-09T02:20:12.059Z,1562638812.059 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-09T02:20:12.059Z,1562638812.059 [Default:CheckIn] Stopped 2019-07-09T02:20:12.059Z,1562638812.059 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-09T02:20:12.059Z,1562638812.059 [Default:CheckIn](INFO): Running loop #28 2019-07-09T02:20:12.060Z,1562638812.060 [Default:CheckIn] Running Loop=28 2019-07-09T02:20:12.060Z,1562638812.060 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-09T02:20:12.060Z,1562638812.060 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-09T02:20:13.653Z,1562638813.653 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-07-09T02:20:13.653Z,1562638813.653 [NAL9602] Data Fault, FailCount= 4 2019-07-09T02:20:13.653Z,1562638813.653 [NAL9602](ERROR): Data Fault 2019-07-09T02:20:13.701Z,1562638813.701 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-09T02:20:14.053Z,1562638814.053 [NAL9602](INFO): Powering down 2019-07-09T02:20:14.919Z,1562638814.919 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-09T02:20:14.919Z,1562638814.919 [NAL9602] No Fault, FailCount= 4 2019-07-09T02:20:44.357Z,1562638844.357 [NAL9602](INFO): Powering up NAL9602 2019-07-09T02:20:55.265Z,1562638855.265 [NAL9602](INFO): NAL9602 initialized 2019-07-09T02:20:56.083Z,1562638856.083 [NAL9602](DEBUG): Fix Requested 2019-07-09T02:25:12.238Z,1562639112.238 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-09T02:20:12.1Z 2019-07-09T02:25:12.238Z,1562639112.238 [Default:CheckIn:Read_GPS] Stopped 2019-07-09T02:25:12.239Z,1562639112.239 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-09T02:25:19.755Z,1562639119.755 [DataOverHttps](INFO): Sending 223 bytes from file Logs/20190708T221730/Express0085.lzma 2019-07-09T02:25:20.561Z,1562639120.561 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0085.lzma.bak 2019-07-09T02:25:20.561Z,1562639120.561 [DataOverHttps](INFO): SBD MOMSN=11434247 2019-07-09T02:25:23.138Z,1562639123.138 [Default:CheckIn:Read_Iridium] Stopped 2019-07-09T02:25:23.138Z,1562639123.138 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-09T02:25:23.138Z,1562639123.138 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-09T02:25:58.671Z,1562639158.671 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-09T02:26:29.377Z,1562639189.377 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-09T02:26:49.914Z,1562639209.914 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.197880 2019-07-09T02:27:33.723Z,1562639253.723 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003308 2019-07-09T02:29:14.339Z,1562639354.339 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout 2019-07-09T02:29:14.339Z,1562639354.339 [RDI_Pathfinder] Communications Fault, FailCount= 1 2019-07-09T02:29:14.339Z,1562639354.339 [RDI_Pathfinder](ERROR): Communications Fault 2019-07-09T02:29:14.340Z,1562639354.340 [RDI_Pathfinder](ERROR): Failed to parse: 2019-07-09T02:29:14.400Z,1562639354.400 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder 2019-07-09T02:29:14.699Z,1562639354.699 [RDI_Pathfinder](INFO): Powering down 2019-07-09T02:29:15.467Z,1562639355.467 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder 2019-07-09T02:29:15.471Z,1562639355.471 [RDI_Pathfinder] No Fault, FailCount= 1 2019-07-09T02:29:28.781Z,1562639368.781 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder 2019-07-09T02:29:44.140Z,1562639384.140 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-09T02:29:44.140Z,1562639384.140 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-07-09T02:30:23.765Z,1562639423.765 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-09T02:30:23.765Z,1562639423.765 [Default:CheckIn:C.Wait] Stopped 2019-07-09T02:30:23.765Z,1562639423.765 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-09T02:30:23.765Z,1562639423.765 [Default:CheckIn:D] Running Loop=1 2019-07-09T02:30:24.148Z,1562639424.148 [Default:CheckIn:D] Stopped 2019-07-09T02:30:24.148Z,1562639424.148 [Default:CheckIn:E] Running Loop=1 2019-07-09T02:30:24.536Z,1562639424.536 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 253.016097 min 2019-07-09T02:30:24.536Z,1562639424.536 [Default:CheckIn:E] Stopped 2019-07-09T02:30:24.536Z,1562639424.536 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-09T02:30:24.536Z,1562639424.536 [Default:CheckIn] Stopped 2019-07-09T02:30:24.536Z,1562639424.536 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-09T02:30:24.536Z,1562639424.536 [Default:CheckIn](INFO): Running loop #29 2019-07-09T02:30:24.536Z,1562639424.536 [Default:CheckIn] Running Loop=29 2019-07-09T02:30:24.536Z,1562639424.536 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-09T02:30:24.536Z,1562639424.536 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-09T02:30:26.135Z,1562639426.135 [NAL9602](DEBUG): Fix Requested 2019-07-09T02:30:57.234Z,1562639457.234 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-07-09T02:30:57.315Z,1562639457.315 [NAL9602](FAULT): received: +CSQ:0 OK99, 2, 0, 0, 0 OK 2019-07-09T02:30:57.315Z,1562639457.315 [NAL9602] Data Fault, FailCount= 5 2019-07-09T02:30:57.315Z,1562639457.315 [NAL9602](ERROR): Data Fault 2019-07-09T02:30:57.375Z,1562639457.375 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-09T02:30:57.376Z,1562639457.376 [CBIT](CRITICAL): Data Fault in component: NAL9602 2019-07-09T02:30:57.637Z,1562639457.637 [NAL9602](INFO): Powering down 2019-07-09T02:30:57.673Z,1562639457.673 [CBIT](INFO): Critical error at 20190709T023057 2019-07-09T02:32:57.659Z,1562639577.659 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-09T02:32:57.659Z,1562639577.659 [NAL9602] No Fault, FailCount= 5 2019-07-09T02:32:58.029Z,1562639578.029 [NAL9602](INFO): Powering up NAL9602 2019-07-09T02:33:08.937Z,1562639588.937 [NAL9602](INFO): NAL9602 initialized 2019-07-09T02:33:09.745Z,1562639589.745 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-07-09T02:33:09.745Z,1562639589.745 [NAL9602] Data Fault, FailCount= 1 2019-07-09T02:33:09.745Z,1562639589.745 [NAL9602](ERROR): Data Fault 2019-07-09T02:33:09.804Z,1562639589.804 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-09T02:33:10.145Z,1562639590.145 [NAL9602](INFO): Powering down 2019-07-09T02:33:10.999Z,1562639590.999 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-09T02:33:10.999Z,1562639590.999 [NAL9602] No Fault, FailCount= 1 2019-07-09T02:33:40.451Z,1562639620.451 [NAL9602](INFO): Powering up NAL9602 2019-07-09T02:33:51.354Z,1562639631.354 [NAL9602](INFO): NAL9602 initialized 2019-07-09T02:33:52.171Z,1562639632.171 [NAL9602](DEBUG): Fix Requested 2019-07-09T02:35:24.718Z,1562639724.718 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-09T02:30:24.5Z 2019-07-09T02:35:24.718Z,1562639724.718 [Default:CheckIn:Read_GPS] Stopped 2019-07-09T02:35:24.719Z,1562639724.719 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-09T02:35:28.777Z,1562639728.777 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-09T02:35:32.131Z,1562639732.131 [DataOverHttps](INFO): Sending 69 bytes from file Logs/20190708T221730/Courier0087.lzma 2019-07-09T02:35:32.937Z,1562639732.937 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Courier0087.lzma.bak 2019-07-09T02:35:32.937Z,1562639732.937 [DataOverHttps](INFO): SBD MOMSN=11434252 2019-07-09T02:35:56.012Z,1562639756.012 [DataOverHttps](INFO): Sending 263 bytes from file Logs/20190708T221730/Express0088.lzma 2019-07-09T02:35:56.276Z,1562639756.276 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-09T02:35:56.277Z,1562639756.277 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-07-09T02:35:56.817Z,1562639756.817 [DataOverHttps](INFO): Moved sent file to Logs/20190708T221730/Express0088.lzma.bak 2019-07-09T02:35:56.817Z,1562639756.817 [DataOverHttps](INFO): SBD MOMSN=11434255 2019-07-09T02:35:59.481Z,1562639759.481 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-09T02:35:59.526Z,1562639759.526 [Default:CheckIn:Read_Iridium] Stopped 2019-07-09T02:35:59.527Z,1562639759.527 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-09T02:35:59.527Z,1562639759.527 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-09T02:41:00.096Z,1562640060.096 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-09T02:41:00.096Z,1562640060.096 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-07-09T02:41:00.105Z,1562640060.105 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-09T02:41:00.106Z,1562640060.106 [Default:CheckIn:C.Wait] Stopped 2019-07-09T02:41:00.106Z,1562640060.106 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-09T02:41:00.106Z,1562640060.106 [Default:CheckIn:D] Running Loop=1 2019-07-09T02:41:00.518Z,1562640060.518 [Default:CheckIn:D] Stopped 2019-07-09T02:41:00.518Z,1562640060.518 [Default:CheckIn:E] Running Loop=1 2019-07-09T02:41:00.947Z,1562640060.947 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 263.622266 min 2019-07-09T02:41:00.947Z,1562640060.947 [Default:CheckIn:E] Stopped 2019-07-09T02:41:00.947Z,1562640060.947 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-09T02:41:00.948Z,1562640060.948 [Default:CheckIn] Stopped 2019-07-09T02:41:00.948Z,1562640060.948 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-09T02:41:00.948Z,1562640060.948 [Default:CheckIn](INFO): Running loop #30 2019-07-09T02:41:00.948Z,1562640060.948 [Default:CheckIn] Running Loop=30 2019-07-09T02:41:00.948Z,1562640060.948 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-09T02:41:00.948Z,1562640060.948 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-09T02:41:02.515Z,1562640062.515 [NAL9602](DEBUG): Fix Requested 2019-07-09T02:41:46.725Z,1562640106.724 [DataOverHttps](IMPORTANT): SBD MTMSN=20190709T024134 2019-07-09T02:42:02.003Z,1562640122.003 [DataOverHttps](INFO): Received command:configSet Micromodem.loadAtStartup 0 bool persist 2019-07-09T02:42:02.167Z,1562640122.167 [CommandLine](IMPORTANT): got command configSet Micromodem.loadAtStartup 0.000000 bool persist 2019-07-09T02:42:02.168Z,1562640122.168 [CommandLine](IMPORTANT): configSet Micromodem.loadAtStartup requires a restart to take effect. 2019-07-09T02:42:02.808Z,1562640122.808 [DataOverHttps](IMPORTANT): SBD MTMSN=20190709T024150 2019-07-09T02:42:16.615Z,1562640136.615 [DataOverHttps](INFO): Received command:restart app 2019-07-09T02:42:16.620Z,1562640136.620 [CommandLine](IMPORTANT): got command restart application 2019-07-09T02:42:17.623Z,1562640137.623 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2019-07-09T02:42:17.624Z,1562640137.624 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:17.695Z,1562640137.695 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2019-07-09T02:42:17.695Z,1562640137.695 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:17.696Z,1562640137.696 [CommandLine](INFO): Join timeout helper Thread ID is 9587 2019-07-09T02:42:17.703Z,1562640137.703 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2019-07-09T02:42:17.703Z,1562640137.703 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:17.704Z,1562640137.704 [NavChartDb](INFO): Join timeout helper Thread ID is 9588 2019-07-09T02:42:17.855Z,1562640137.855 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2019-07-09T02:42:17.856Z,1562640137.856 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:17.871Z,1562640137.871 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler 2019-07-09T02:42:17.871Z,1562640137.871 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:17.872Z,1562640137.872 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 9589 2019-07-09T02:42:18.127Z,1562640138.127 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread. 2019-07-09T02:42:18.128Z,1562640138.128 [WetLabsSeaOWL_UV_A](INFO): Powering down 2019-07-09T02:42:18.128Z,1562640138.128 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:18.135Z,1562640138.135 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler 2019-07-09T02:42:18.135Z,1562640138.135 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:18.136Z,1562640138.136 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 9590 2019-07-09T02:42:18.143Z,1562640138.143 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread. 2019-07-09T02:42:18.144Z,1562640138.144 [CTD_NeilBrown](INFO): Powering down 2019-07-09T02:42:18.155Z,1562640138.155 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:18.156Z,1562640138.156 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2019-07-09T02:42:18.156Z,1562640138.156 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:18.156Z,1562640138.156 [Radio_Surface](INFO): Join timeout helper Thread ID is 9591 2019-07-09T02:42:18.231Z,1562640138.231 [Radio_Surface](INFO): Powering down 2019-07-09T02:42:18.232Z,1562640138.232 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2019-07-09T02:42:18.233Z,1562640138.233 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:18.236Z,1562640138.236 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2019-07-09T02:42:18.236Z,1562640138.236 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:18.237Z,1562640138.237 [DataOverHttps](INFO): Join timeout helper Thread ID is 9592 2019-07-09T02:42:18.631Z,1562640138.631 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2019-07-09T02:42:18.632Z,1562640138.632 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:18.640Z,1562640138.640 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2019-07-09T02:42:18.640Z,1562640138.640 [logger ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:18.640Z,1562640138.640 [logger](INFO): Join timeout helper Thread ID is 9593 2019-07-09T02:42:18.728Z,1562640138.728 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2019-07-09T02:42:18.728Z,1562640138.728 [logger ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:18.740Z,1562640138.740 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2019-07-09T02:42:18.740Z,1562640138.740 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:18.740Z,1562640138.740 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2019-07-09T02:42:18.740Z,1562640138.740 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:18.741Z,1562640138.741 [controlThread](INFO): Join timeout helper Thread ID is 9594 2019-07-09T02:42:18.803Z,1562640138.803 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2019-07-09T02:42:18.804Z,1562640138.804 [controlThread](DEBUG): Uninitializing ControlThread 2019-07-09T02:42:18.804Z,1562640138.804 [AHRS_M2](INFO): Powering down 2019-07-09T02:42:18.876Z,1562640138.876 [DUSBL_Hydroid](INFO): Powering down 2019-07-09T02:42:18.948Z,1562640138.948 [Micromodem](INFO): Powering down 2019-07-09T02:42:19.044Z,1562640139.044 [NAL9602](INFO): Powering down 2019-07-09T02:42:19.115Z,1562640139.115 [RDI_Pathfinder](INFO): Powering down 2019-07-09T02:42:19.117Z,1562640139.117 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2019-07-09T02:42:19.118Z,1562640139.118 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2019-07-09T02:42:19.118Z,1562640139.118 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2019-07-09T02:42:19.119Z,1562640139.119 [MissionManager](INFO): Uninitializing Mission Default 2019-07-09T02:42:19.119Z,1562640139.119 [Default] Stopped 2019-07-09T02:42:19.119Z,1562640139.119 [Default](DEBUG): Aggregate::uninitialize Default 2019-07-09T02:42:19.119Z,1562640139.119 [Default:B.GoToSurface] Stopped 2019-07-09T02:42:19.119Z,1562640139.119 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-07-09T02:42:19.119Z,1562640139.119 [Default:CheckIn] Stopped 2019-07-09T02:42:19.119Z,1562640139.119 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-09T02:42:19.119Z,1562640139.119 [Default:CheckIn:Read_GPS] Stopped 2019-07-09T02:42:19.122Z,1562640139.122 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2019-07-09T02:42:19.122Z,1562640139.122 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2019-07-09T02:42:19.123Z,1562640139.123 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2019-07-09T02:42:19.123Z,1562640139.123 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2019-07-09T02:42:19.123Z,1562640139.123 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2019-07-09T02:42:19.123Z,1562640139.123 [BuoyancyServo](INFO): Powering down 2019-07-09T02:42:19.135Z,1562640139.135 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2019-07-09T02:42:19.135Z,1562640139.135 [ElevatorServo](INFO): Powering down 2019-07-09T02:42:19.136Z,1562640139.136 [MassServo](DEBUG): Uninitialize Mass Servo. 2019-07-09T02:42:19.136Z,1562640139.136 [MassServo](INFO): Powering down 2019-07-09T02:42:19.137Z,1562640139.137 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-07-09T02:42:19.137Z,1562640139.137 [RudderServo](INFO): Powering down 2019-07-09T02:42:19.138Z,1562640139.138 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2019-07-09T02:42:19.138Z,1562640139.138 [ThrusterServo](INFO): Powering down 2019-07-09T02:42:19.139Z,1562640139.139 [SBIT](DEBUG): Uninitialize SBIT Component. 2019-07-09T02:42:19.139Z,1562640139.139 [IBIT](DEBUG): Uninitialize IBIT Component. 2019-07-09T02:42:19.140Z,1562640139.140 [CBIT](DEBUG): Uninitialize CBIT Component. 2019-07-09T02:42:19.140Z,1562640139.140 [CBIT](DEBUG): Powering off loads. 2019-07-09T02:42:19.151Z,1562640139.151 [CBIT](DEBUG): Disabling WDT. 2019-07-09T02:42:19.163Z,1562640139.163 [CBIT](DEBUG): Opening all GF detection circuits. 2019-07-09T02:42:19.164Z,1562640139.164 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:19.216Z,1562640139.216 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:19.225Z,1562640139.225 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:19.266Z,1562640139.266 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:19.268Z,1562640139.268 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:19.325Z,1562640139.325 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-07-09T02:42:19.397Z,1562640139.397 [logger ThreadHandler](INFO): Thread cancelled.