Merge pull request #127 from uniba-swt/improve-logging

Pull Logging and Logic Improvements

.github/workflows/ci.yml

@@ -21,19 +21,19 @@ jobs:
     - uses: actions/checkout@v3
 
     - name: Install cmocka
-      run: sudo apt-get install -y --no-install-recommends libyaml-dev libcmocka-dev
+      run: sudo apt update; sudo apt-get install -y --no-install-recommends libyaml-dev libcmocka-dev
 
     - name: Build libbidib
       run: git clone --depth 1 https://github.com/uniba-swt/libbidib.git; cd libbidib; mkdir bin; cd bin; cmake ..; make -j; sudo make -j install
 
     - name: Install pam, gnutls
-      run: sudo apt-get install -y --no-install-recommends libpam0g-dev libgnutls28-dev
+      run: sudo apt update; sudo apt-get install -y --no-install-recommends libpam0g-dev libgnutls28-dev
 
     - name: Build libonion
       run: git clone --depth 1 https://github.com/uniba-swt/onion.git; cd onion; mkdir bin; cd bin; cmake -DONION_EXAMPLES=false -DONION_USE_TESTS=false ..; make -j onion; make -j onion_static; sudo make -j install
 
     - name: Install flex-dev, graphviz
-      run: sudo apt-get install -y libfl-dev graphviz
+      run: sudo apt update; sudo apt-get install -y libfl-dev graphviz
 
     - name: Install forecc
       run: git clone --depth 1 https://github.com/PRETgroup/ForeC.git; cd ForeC/ForeC\ Compiler; make -j; echo "FOREC_COMPILER_PATH=`pwd`" >> $GITHUB_ENV

README.md

@@ -213,3 +213,29 @@ When is a grab-id reset?
 is not the same as the one at the server
 * If the user issues `swtbahn admin shutdown` and the system was running
 * If the user issues `swtbahn config`
+
+## Logging Format Notes
+We try to use a consistent logging format in all request handlers. General workflow of how request handlers generate log messages:
+1. Parse form data.
+2. Validate form data. If validation fails, make a log on `ERROR` level and stop processing.
+3. Make a log on log level `NOTICE` that represents the start of processing, with ` - start` at the end of the log.
+4. Process request. If processing causes an error, make a log on the `ERROR` or `WARNING` log level with ` - abort` at the end of the log and stop processing.
+5. Processing concluded. Indicate this by printing the log message of Step 3 again, on the same log level, with ` - finish` instead of ` - start` at the end.
+
+For request handlers that barely do any "processing" at all; e.g. where only a status variable is updated, they only generate one log message that ends with ` - done`.
+Request handlers that only return information (getters) also use the ` - done` pattern instead of `start` and `finish`, and use the log level `INFO` for the ` - done` log.
+
+As an example, when a request is made to set point10 to the normal state, the request handler (`handler_set_point`) generates the following log messages when the processing is successful:
+> LOG_NOTICE: `Request: Set point - point: point10 state: normal - start`   
+> _Intervening log messages from internal processing_   
+> LOG_NOTICE: `Request: Set point - point: point10 state: normal - finish`   
+
+If the above request was instead made with an unsupported state, e.g., `foobar`, then the request handler would generate the following log messages to say that the processing was stopped because of invalid parameters: 
+
+> LOG_NOTICE: `Request: Set point - point: point10 state: foobar - start`   
+> _Intervening log messages from internal processing_   
+> LOG_ERR: `Request: Set point - point: point10 state: foobar - invalid parameters - abort`   
+
+If the above request forgot to specify the state, i.e., the state parameter is `null`, then the request handler would only generate the following log message to say that the parameter validation failed:
+
+>  LOG_ERR: `Request: Set point - invalid parameters`

server/src/bahn_data_util.c

@@ -563,13 +563,16 @@ bool config_set_scalar_string_value(const char *type, const char *id, const char
             t_interlocking_route *route = (t_interlocking_route *) obj;
             route->train = strdup(value);
             if (value != NULL && route->train == NULL) {
-                syslog_server(LOG_ERR, "config set scalar string value: unable to allocate memory for route->train");
+                syslog_server(LOG_ERR, 
+                              "config set scalar string value: unable to allocate memory for route->train");
             }
             result = true;
         }
     }
 
-    syslog_server(LOG_DEBUG, "Set scalar string: %s %s.%s = %s => %s", type, id, prop_name, value, result ? "true" : "false");
+    syslog_server(LOG_DEBUG, 
+                  "Set scalar string: %s %s.%s = %s => %s", 
+                  type, id, prop_name, value, result ? "true" : "false");
     return result;
 }
 

server/src/dyn_containers_interface.c

@@ -146,11 +146,13 @@ static void *dyn_containers_actuate(void *_) {
 												  ? engine_instance->output_nominal_speed 
 												  : -engine_instance->output_nominal_speed, 
 												  grabbed_trains[i].track_output)) {
-							syslog_server(LOG_ERR, "Request: Set train speed - train: %s: bad parameter values",
+							syslog_server(LOG_ERR, 
+							              "Dyn containers actuate - train: %s - invalid parameters",
 							              grabbed_trains[i].name->str);
 						} else {
 							bidib_flush();
-							syslog_server(LOG_NOTICE, "Request: Set train speed - train: %s speed: %d",
+							syslog_server(LOG_NOTICE, 
+							              "Dyn containers actuate - train: %s speed: %d - set train speed",
 							              grabbed_trains[i].name->str, 
 							              engine_instance->output_nominal_forwards 
 							              ? engine_instance->output_nominal_speed