Merge pull request #47 from NOAA-MDL/45-update-iwxxmd

Update to monitor watchdog's observer as well

demo/README.md

@@ -3,7 +3,7 @@
 To illustrate the use of GIFTs, this subdirectory contains two simple python programs.
 
 ### demo1.py
-demo1.py makes use of a small aerodrome database and sample files that we'll use to translate the TAC forms into IWXXM documents.  This demonstration program requires the Python Tk/Tcl package which is readily available with Python v3.9+. 
+demo1.py makes use of a small aerodrome database and sample files that we'll use to translate the TAC forms into IWXXM documents.  This demonstration program requires the Python Tk/Tcl package which is readily available with Python v3.9+.
 
     $ cd GIFTs/demo
     $ demo1.py
@@ -33,7 +33,7 @@ The second observation with a decoding problem:
     METAR LGKL 110120Z 00000KT 9999 SCT03O 18/16 Q1012
                                     ^
     Expecting directional minimum visibility or runway visual range or precipitation or obstruction to vision or precipitation in the vicinity or NCD, NSC or vertical visibility or cloud layer
- 
+
 The caret indicates that the decoder doesn't understand the scattered cloud layer at 3,000 ft. Do you see why? There are typos: a capital O was used in place of a zero, 0.  For some fonts, the difference between the two characters are subtle. This illustrates that the decoder must understand everything in the TAC report in order to properly encode the data into XML. By fixing these typos, the IWXXM message for aerodrome LGKL can be created and the LGKL TAC can now be decoded cleanly by others as well.
 
 The remaining METAR reports were decoded without issues and their data encoded into IWXXM and packaged up in an Meteorological Bulletin.
@@ -55,7 +55,7 @@ This means that for the METAR, SPECI and TAF, the product starts with one of tho
 The WMO AHL line in the TAC file is critical in forming the proper filename for the IWXXM Meteorological Bulletin, which is shown in the 'IWXXM XML file" text field.  The format of the filename follows the specifications outlined for Aviation XML products in WMO No. 368 Manual on the Global Telecommunication System.
 
 ### iwxxmd.py
-This program runs as a UNIX/Linux [daemon](https://en.wikipedia.org/wiki/Daemon_(computing)) that mostly sleeps as a background process, occasionally waking up when new, recently arrived TAC form messages arrive in a monitored filesystem directory. The daemon then translates the file's contents into the IWXXM form and write a new XML file to a separate directory. When no more TAC messages arrive, the daemon goes back to sleep to be awakened again when a new TAC message arrives.
+This program runs as a UNIX/Linux [daemon](https://en.wikipedia.org/wiki/Daemon_(computing)) that sleeps in the background and awakens when files arrive in the monitored directory. The daemon--provided the files can be correctly parsed (see above for expected TAC file formats)--translates the files' contents into IWXXM form and writes the corresponding XML files into a separate directory. It then goes back to sleep when there are no more files to process.
 
 `iwxxmd.py` does require Python's watchdog module to be installed like so,
 
@@ -65,6 +65,12 @@ The associated configuration template file, `iwxxmd.cfg`, is well documented int
 
     $ iwxxmd.py metar.cfg
 
-By copying the template file with new names as needed, several IWXXM daemons can run simultaneously.
+By copying the template file with new names as needed, several IWXXM daemons can run simultaneously each processing a specific product.
+
+Any misconfiguration will result in an error message being written to the console and the daemon will not start. Like most UNIX/Linux daemons, the process can run indefinitely in the background. Should the daemon run into any difficulties, it will write messages to its log file.  The log file name format follows this format `<product>_iwxxmd_<DOW>` where `<product>` is one of `'metar'`, `'swa'`, `'taf'`, `'tca'`, or `'vaa'`, and `<DOW>` is the abbreviated day of the week, e.g. `'metar_iwxxmd_Mon'`. When midnight arrives, the daemon will switch to a different log file. Thus, a maximum of seven log files are created with each file being overwritten after 6 days.
+
+With the 1.5.2 release of GIFTs, the hourly 'I am alive' message was replaced with TAC->XML status messages to indicate real-time activity. Also, new code was added so that the daemon now responds to USR1 signals sent via the UNIX/Linux command:
+
+    $ kill -USR1 <daemon_pid #>
 
-Any misconfiguration will result in an error message being written to the console and the daemon will not start. Like most UNIX/Linux daemons, the process can run indefinitely in the background. Should the daemon run into any difficulties, it will write messages to its log file.  The log file name format follows this format `<product>_iwxxmd_<DOW>` where `<product>` is one of `'metar'`, `'swa'`, `'taf'`, `'tca'`, or `'vaa'`, and `<DOW>` is the abbreviated day of the week, e.g. `'metar_iwxxmd_Mon'`. The daemon will 'ping' to the log file every hour to indicate that it is 'alive'. While active, the daemon will report the files read in and the files written out. When midnight arrives, the daemon will switch to a different log file. Thus, a maximum of seven log files are created with each file being overwritten after 6 days.
+When the USR1 signal is received the daemon alternates in (not) writing DEBUG level messages to the log file. Finally, the daemon now checks once per minute to make sure watchdog's observer is 'alive'. If not, a new observer is started automatically and incoming directory monitoring continues uninterrupted.

demo/iwxxmd.py

@@ -112,16 +112,21 @@ def __init__(self, encoder, delete_flag, header, outputDirectory):
         self.delete_flag = delete_flag
         self.header = header
         self.outputDirectory = outputDirectory
-        self.bulletin = gifts.bulletin.Bulletin()
 
         if self.header:
             self.ext = 'txt'
         else:
             self.ext = 'xml'
 
+        self.ticks = 0
+    #
+    # If you find that the daemon misses incoming TAC files, consider changing this function name from 'on_closed' to
+    # 'on_modified'.
+
     def on_closed(self, event):
         """If a new file saved in monitored directory, read it."""
 
+        self.ticks = 0
         if not event.is_directory:
             try:
                 #
@@ -149,13 +154,13 @@ def on_closed(self, event):
                 bulletin = self.encoder.encode(tac)
                 iwxxm_msg_cnt = len(bulletin)
                 if iwxxm_msg_cnt:
-                    self.logger.debug(f'{iwxxm_msg_cnt} IWXXM products generated from {event.src_path} contents')
+                    self.logger.info(f'{iwxxm_msg_cnt} IWXXM documents generated from file {event.src_path} contents')
                     bulletin.write(self.outputDirectory, header=self.header)
 
                 del bulletin
 
             except Exception:
-                self.logger.exception('Unable to convert TAC to XML. Reason:\n')
+                self.logger.exception(f'Unable to convert TAC {event.src_path} to IWXXM. Reason:\n')
 
 
 class Monitor(Daemon):
@@ -167,6 +172,10 @@ def __init__(self, encoder, delete_flag, header, inputDirectory, outputDirectory
 
         self.logger = logging.getLogger(__name__)
         #
+        # Don't write files into the input directory
+        if os.path.realpath(inputDirectory) == os.path.realpath(outputDirectory):
+            raise SystemExit('Input and output directories should be different')
+        #
         # Check to make sure the monitor can read these directories and modify their contents
         if not os.path.exists(inputDirectory) or not os.path.isdir(inputDirectory) or \
            not os.access(inputDirectory, (os.R_OK | os.W_OK | os.X_OK)):
@@ -182,8 +191,11 @@ def __init__(self, encoder, delete_flag, header, inputDirectory, outputDirectory
         # Start the observer with the the directory to watch and what to do when
         # there's activity in the directory
         self.observer = Observer()
-        self.observer.schedule(self.dispatcher, inputDirectory, False)
         self.inputDirectory = inputDirectory
+        self.observer.schedule(self.dispatcher, self.inputDirectory, recursive=False)
+        #
+        # Toggle logging levels (INFO<=>DEBUG) if a USR1 signal is received
+        signal.signal(signal.SIGUSR1, self.toggleLoggingLevel)
         #
         # Clean up when termination signal is received
         signal.signal(signal.SIGTERM, self.shutdown)
@@ -192,14 +204,37 @@ def run(self):
 
         self.logger.info(f'Begin monitoring {self.inputDirectory}. . .')
         self.observer.start()
-        t = 0
-
+        #
+        # Begin watch . . .
         while True:
+
             time.sleep(0.1)
-            t += 1
-            if t >= 36000:
-                self.logger.info('Aliveness check . . .')
-                t = 0
+            self.dispatcher.ticks += 1
+            #
+            # After a period of no activity by the observer, check it . . .
+            if self.dispatcher.ticks >= 600:
+
+                self.dispatcher.ticks = 0
+                if not self.observer.is_alive():
+                    #
+                    # If observer is no longer alive, spawn a new one
+                    try:
+                        self.logger.debug('Current observer is no longer responding to incoming files.')
+                        self.observer.stop()
+                        self.observer.join()
+
+                        self.logger.debug('Creating new observer . . .')
+                        self.observer = Observer()
+                        self.observer.schedule(self.dispatcher, self.inputDirectory, recursive=False)
+                        self.observer.start()
+
+                    except Exception as err:
+                        self.logger.fatal(str(err))
+
+    def toggleLoggingLevel(self, signum, frame):
+
+        self.logger.setLevel(logging.DEBUG if self.logger.getEffectiveLevel() == logging.INFO else logging.INFO)
+        self.logger.info(f'Changing logging level to {self.logger.getEffectiveLevel()}')
 
     def shutdown(self, signum, frame):
 
@@ -268,30 +303,24 @@ def shutdown(self, signum, frame):
 
     logger = {
         'version': 1,
-        'disable_existing_loggers': False,
 
         'formatters': {
             'default': {
-                'class': 'logging.Formatter',
-                'format': '%(asctime)s %(levelname)-5s %(process)5d %(module)s: %(message)s'
+                'format': '%(asctime)s %(levelname)-5s %(process)5d %(module)s: %(message)s',
+                'style': '%',
+                'validate': True
             },
         },
 
         'handlers': {
             'file': {
-                'level': 'INFO',
                 'formatter': 'default',
-                '()': 'iwxxmd.DOWFileHandler',
+                '()': DOWFileHandler,
                 'directory': f'{logfileDirectory}',
                 'basename': f'{product}_iwxxmd'
             },
         },
-        'loggers': {
-            'gifts': {
-                'propogate': True,
-                'handlers': ['file'],
-            }
-        },
+
         'root': {
             'level': 'INFO',
             'handlers': ['file']