refactoring sp_log_* (#340)

Co-authored-by: Giovanni Dante Grazioli <giovanni.dantegrazioli@nbs-system.com>

7 files changed, 55 insertions, 51 deletions

diff --git a/src/sp_crypt.c b/src/sp_crypt.c
index 42c1510..b353ebe 100644
--- a/src/sp_crypt.c
+++ b/src/sp_crypt.c
@@ -49,16 +49,16 @@ int decrypt_zval(zval *pDest, bool simulation, zend_hash_key *hash_key) {
 
   if (ZSTR_LEN(debase64) < crypto_secretbox_NONCEBYTES) {
     if (true == simulation) {
-      sp_log_msg(
-          "cookie_encryption", SP_LOG_SIMULATION,
+      sp_log_simulation(
+          "cookie_encryption",
           "Buffer underflow tentative detected in cookie encryption handling "
           "for %s. Using the cookie 'as it' instead of decrypting it",
           hash_key ? ZSTR_VAL(hash_key->key) : "the session");
       return ZEND_HASH_APPLY_KEEP;
     } else {
       // LCOV_EXCL_START
-      sp_log_msg(
-          "cookie_encryption", SP_LOG_DROP,
+      sp_log_drop(
+          "cookie_encryption",
           "Buffer underflow tentative detected in cookie encryption handling");
       return ZEND_HASH_APPLY_REMOVE;
       // LCOV_EXCL_STOP
@@ -69,15 +69,15 @@ int decrypt_zval(zval *pDest, bool simulation, zend_hash_key *hash_key) {
   if (ZSTR_LEN(debase64) + (size_t)crypto_secretbox_ZEROBYTES <
       ZSTR_LEN(debase64)) {
     if (true == simulation) {
-      sp_log_msg(
-          "cookie_encryption", SP_LOG_SIMULATION,
+      sp_log_simulation(
+          "cookie_encryption",
           "Integer overflow tentative detected in cookie encryption handling "
           "for %s. Using the cookie 'as it' instead of decrypting it.",
           hash_key ? ZSTR_VAL(hash_key->key) : "the session");
       return ZEND_HASH_APPLY_KEEP;
     } else {
-      sp_log_msg(
-          "cookie_encryption", SP_LOG_DROP,
+      sp_log_drop(
+          "cookie_encryption",
           "Integer overflow tentative detected in cookie encryption handling.");
       return ZEND_HASH_APPLY_REMOVE;
     }
@@ -98,8 +98,8 @@ int decrypt_zval(zval *pDest, bool simulation, zend_hash_key *hash_key) {
 
   if (-1 == ret) {
     if (true == simulation) {
-      sp_log_msg(
-          "cookie_encryption", SP_LOG_SIMULATION,
+      sp_log_simulation(
+          "cookie_encryption",
           "Something went wrong with the decryption of %s. Using the cookie "
           "'as it' instead of decrypting it",
           hash_key ? ZSTR_VAL(hash_key->key) : "the session");
@@ -107,7 +107,7 @@ int decrypt_zval(zval *pDest, bool simulation, zend_hash_key *hash_key) {
       efree(backup);
       return ZEND_HASH_APPLY_KEEP;
     } else {
-      sp_log_msg("cookie_encryption", SP_LOG_WARN,
+      sp_log_warn("cookie_encryption",
                  "Something went wrong with the decryption of %s",
                  hash_key ? ZSTR_VAL(hash_key->key) : "the session");
       efree(backup);
diff --git a/src/sp_disabled_functions.c b/src/sp_disabled_functions.c
index f35f5ca..a7136df 100644
--- a/src/sp_disabled_functions.c
+++ b/src/sp_disabled_functions.c
@@ -574,11 +574,11 @@ ZEND_FUNCTION(eval_blacklist_callback) {
                      SP_TOKEN_EVAL_BLACKLIST);
     }
     if (config_eval->simulation) {
-      sp_log_msg("eval", SP_LOG_SIMULATION,
+      sp_log_simulation("eval",
                  "A call to %s was tried in eval, in %s:%d, logging it.",
                  current_function_name, ZSTR_VAL(filename), line_number);
     } else {
-      sp_log_msg("eval", SP_LOG_DROP,
+      sp_log_drop("eval",
                  "A call to %s was tried in eval, in %s:%d, dropping it.",
                  current_function_name, ZSTR_VAL(filename), line_number);
     }
diff --git a/src/sp_execute.c b/src/sp_execute.c
index 4eae874..73cc560 100644
--- a/src/sp_execute.c
+++ b/src/sp_execute.c
@@ -18,10 +18,10 @@ ZEND_COLD static inline void terminate_if_writable(const char *filename) {
                      SP_TOKEN_READONLY_EXEC);
     }
     if (true == config_ro_exec->simulation) {
-      sp_log_msg("readonly_exec", SP_LOG_SIMULATION,
+      sp_log_simulation("readonly_exec",
                  "Attempted execution of a writable file (%s).", filename);
     } else {
-      sp_log_msg("readonly_exec", SP_LOG_DROP,
+      sp_log_drop("readonly_exec",
                  "Attempted execution of a writable file (%s).", filename);
       zend_bailout();
     }
@@ -79,14 +79,14 @@ is_in_eval_and_whitelisted(const zend_execute_data *execute_data) {
                        SP_TOKEN_EVAL_WHITELIST);
       }
       if (config_eval->simulation) {
-        sp_log_msg(
-            "Eval_whitelist", SP_LOG_SIMULATION,
+        sp_log_simulation(
+            "Eval_whitelist",
             "The function '%s' isn't in the eval whitelist, logging its call.",
             ZSTR_VAL(current_function));
         return;
       } else {
-        sp_log_msg(
-            "Eval_whitelist", SP_LOG_DROP,
+        sp_log_drop(
+            "Eval_whitelist",
             "The function '%s' isn't in the eval whitelist, dropping its call.",
             ZSTR_VAL(current_function));
       }
diff --git a/src/sp_unserialize.c b/src/sp_unserialize.c
index 29706c9..8977dd9 100644
--- a/src/sp_unserialize.c
+++ b/src/sp_unserialize.c
@@ -61,8 +61,7 @@ PHP_FUNCTION(sp_unserialize) {
 
   /* 64 is the length of HMAC-256 */
   if (buf_len < 64) {
-    sp_log_msg("unserialize", SP_LOG_DROP,
-               "The serialized object is too small.");
+    sp_log_drop("unserialize", "The serialized object is too small.");
   }
 
   hmac = buf + buf_len - 64;
@@ -99,16 +98,14 @@ PHP_FUNCTION(sp_unserialize) {
                      SP_TOKEN_UNSERIALIZE_HMAC);
     }
     if (true == config_unserialize->simulation) {
-      sp_log_msg("unserialize", SP_LOG_SIMULATION, "Invalid HMAC for %s",
-                 serialized_str);
+      sp_log_simulation("unserialize", "Invalid HMAC for %s", serialized_str);
       if ((orig_handler = zend_hash_str_find_ptr(
                SNUFFLEUPAGUS_G(sp_internal_functions_hook), "unserialize",
                sizeof("unserialize") - 1))) {
         orig_handler(INTERNAL_FUNCTION_PARAM_PASSTHRU);
       }
     } else {
-      sp_log_msg("unserialize", SP_LOG_DROP, "Invalid HMAC for %s",
-                 serialized_str);
+      sp_log_drop("unserialize", "Invalid HMAC for %s", serialized_str);
     }
   }
   efree(serialized_str);
diff --git a/src/sp_upload_validation.c b/src/sp_upload_validation.c
index 54b0481..4ee7bd7 100644
--- a/src/sp_upload_validation.c
+++ b/src/sp_upload_validation.c
@@ -13,7 +13,7 @@ int sp_rfc1867_callback(unsigned int event, void *event_data, void **extra);
 
 int sp_rfc1867_callback_win(unsigned int event, void *event_data,
                             void **extra) {
-  sp_log_msg("upload_validation", SP_LOG_SIMULATION,
+  sp_log_simulation("upload_validation",
              "The upload validation doesn't work for now on Windows yet, "
              "see https://github.com/jvoisin/snuffleupagus/issues/248 for "
              "details.");
@@ -90,9 +90,9 @@ int sp_rfc1867_callback(unsigned int event, void *event_data, void **extra) {
       if (WEXITSTATUS(waitstatus) != 0) {  // Nope
         char *uri = getenv("REQUEST_URI");
         int sim = config_upload->simulation;
-        sp_log_msg("upload_validation", sim ? SP_LOG_SIMULATION : SP_LOG_DROP,
-                   "The upload of %s on %s was rejected.", filename,
-                   uri ? uri : "?");
+        sp_log_auto("upload_validation", sim,
+            "The upload of %s on %s was rejected.",
+            filename, uri ? uri : "?");
       }
     }
     ZEND_HASH_FOREACH_END();
diff --git a/src/sp_utils.c b/src/sp_utils.c
index 146fe77..8032e0a 100644
--- a/src/sp_utils.c
+++ b/src/sp_utils.c
@@ -40,7 +40,7 @@ const char* get_ipaddr() {
   return default_ipaddr;
 }
 
-void sp_log_msg(char const* restrict feature, int type,
+void sp_log_msgf(char const* restrict feature, int level, int type,
                 const char* restrict fmt, ...) {
   char* msg;
   va_list args;
@@ -51,16 +51,14 @@ void sp_log_msg(char const* restrict feature, int type,
 
   const char* client_ip = get_ipaddr();
   const char* logtype = NULL;
-  int bailout = type == SP_LOG_DROP;
   switch(type) {
-    case SP_LOG_SIMULATION:
+    case SP_TYPE_SIMULATION:
       logtype = "simulation";
-      type = E_WARNING;
       break;
-    case SP_LOG_DROP:
+    case SP_TYPE_DROP:
       logtype = "drop";
-      type = E_ERROR;
       break;
+    case SP_TYPE_LOG:
     default:
       logtype = "log";
       break;
@@ -69,20 +67,20 @@ void sp_log_msg(char const* restrict feature, int type,
   switch (SNUFFLEUPAGUS_G(config).log_media) {
     case SP_SYSLOG: {
       const char* error_filename = zend_get_executed_filename();
-      int syslog_level = (type == E_ERROR) ? LOG_ERR : LOG_INFO;
+      int syslog_level = (level == E_ERROR) ? LOG_ERR : LOG_INFO;
       int error_lineno = zend_get_executed_lineno(TSRMLS_C);
       openlog(PHP_SNUFFLEUPAGUS_EXTNAME, LOG_PID, LOG_AUTH);
       syslog(syslog_level, "[snuffleupagus][%s][%s][%s] %s in %s on line %d",
              client_ip, feature, logtype, msg, error_filename, error_lineno);
       closelog();
-      if (bailout) {
+      if (type == SP_TYPE_DROP) {
         zend_bailout();
       }
       break;
     }
     case SP_ZEND:
     default:
-      zend_error(type, "[snuffleupagus][%s][%s][%s] %s", client_ip, feature, logtype, msg);
+      zend_error(level, "[snuffleupagus][%s][%s][%s] %s", client_ip, feature, logtype, msg);
       break;
   }
 }
@@ -282,12 +280,12 @@ void sp_log_disable(const char* restrict path, const char* restrict arg_name,
       char_repr = zend_string_to_char(arg_value);
     }
     if (alias) {
-      sp_log_msg("disabled_function", sim ? SP_LOG_SIMULATION : SP_LOG_DROP,
+      sp_log_auto("disabled_function", sim,
                  "Aborted execution on call of the function '%s', "
                  "because its argument '%s' content (%s) matched the rule '%s'",
                  path, arg_name, char_repr ? char_repr : "?", ZSTR_VAL(alias));
     } else {
-      sp_log_msg("disabled_function", sim ? SP_LOG_SIMULATION : SP_LOG_DROP,
+      sp_log_auto("disabled_function", sim,
                  "Aborted execution on call of the function '%s', "
                  "because its argument '%s' content (%s) matched a rule",
                  path, arg_name, char_repr ? char_repr : "?");
@@ -295,12 +293,12 @@ void sp_log_disable(const char* restrict path, const char* restrict arg_name,
     efree(char_repr);
   } else {
     if (alias) {
-      sp_log_msg("disabled_function", sim ? SP_LOG_SIMULATION : SP_LOG_DROP,
+      sp_log_auto("disabled_function", sim,
                  "Aborted execution on call of the function '%s', "
                  "because of the the rule '%s'",
                  path, ZSTR_VAL(alias));
     } else {
-      sp_log_msg("disabled_function", sim ? SP_LOG_SIMULATION : SP_LOG_DROP,
+      sp_log_auto("disabled_function", sim,
                  "Aborted execution on call of the function '%s'", path);
     }
   }
@@ -322,13 +320,13 @@ void sp_log_disable_ret(const char* restrict path,
     char_repr = zend_string_to_char(ret_value);
   }
   if (alias) {
-    sp_log_msg(
-        "disabled_function", sim ? SP_LOG_SIMULATION : SP_LOG_DROP,
+    sp_log_auto(
+        "disabled_function", sim,
         "Aborted execution on return of the function '%s', "
         "because the function returned '%s', which matched the rule '%s'",
         path, char_repr ? char_repr : "?", ZSTR_VAL(alias));
   } else {
-    sp_log_msg("disabled_function", sim ? SP_LOG_SIMULATION : SP_LOG_DROP,
+    sp_log_auto("disabled_function", sim,
                "Aborted execution on return of the function '%s', "
                "because the function returned '%s', which matched a rule",
                path, char_repr ? char_repr : "?");
diff --git a/src/sp_utils.h b/src/sp_utils.h
index 91a5a20..744bbff 100644
--- a/src/sp_utils.h
+++ b/src/sp_utils.h
@@ -28,16 +28,25 @@
 #define HOOK_FUNCTION_BY_REGEXP(regexp, hook_table, new_function) \
   hook_regexp(regexp, SNUFFLEUPAGUS_G(hook_table), new_function)
 
-#define SP_LOG_SIMULATION 0x100000
-#define SP_LOG_DROP 0x200000
+#define SP_TYPE_LOG (0)
+#define SP_TYPE_DROP (1)
+#define SP_TYPE_SIMULATION (2)
+
 #define SP_LOG_DEBUG E_NOTICE
 #define SP_LOG_ERROR E_ERROR
 #define SP_LOG_WARN E_WARNING
 
-#define sp_log_err(feature, ...) sp_log_msg(feature, SP_LOG_ERROR, __VA_ARGS__)
-#define sp_log_warn(feature, ...) sp_log_msg(feature, SP_LOG_WARN, __VA_ARGS__)
+#define sp_log_msg(feature, level, ...) sp_log_msgf(feature, level, SP_TYPE_LOG, __VA_ARGS__)
+#define sp_log_drop(feature, ...) sp_log_msgf(feature, SP_LOG_ERROR, SP_TYPE_DROP, __VA_ARGS__)
+#define sp_log_simulation(feature, ...) sp_log_msgf(feature, SP_LOG_WARN, SP_TYPE_SIMULATION, __VA_ARGS__)
+#define sp_log_auto(feature, is_simulation, ...) sp_log_msgf(feature, \
+  (is_simulation ? SP_LOG_WARN : SP_LOG_ERROR), \
+  (is_simulation ? SP_TYPE_SIMULATION : SP_TYPE_DROP), __VA_ARGS__)
+
+#define sp_log_err(feature, ...) sp_log_msgf(feature, SP_LOG_ERROR, SP_TYPE_LOG, __VA_ARGS__)
+#define sp_log_warn(feature, ...) sp_log_msgf(feature, SP_LOG_WARN, SP_TYPE_LOG, __VA_ARGS__)
 #ifdef SP_DEBUG
-#define sp_log_debug(...) sp_log_msg("DEBUG", SP_LOG_DEBUG, __VA_ARGS__)
+#define sp_log_debug(...) sp_log_msgf("DEBUG", SP_LOG_DEBUG, SP_TYPE_LOG, __VA_ARGS__)
 #else
 #define sp_log_debug(...)
 #endif
@@ -45,7 +54,7 @@
 #define GET_SUFFIX(x) (x == 1) ? "st" : ((x == 2) ? "nd" : "th")
 
 const char *get_ipaddr();
-void sp_log_msg(char const *restrict feature, int type,
+void sp_log_msgf(char const *restrict feature, int level, int type,
                 const char *restrict fmt, ...);
 int compute_hash(const char *const restrict filename, char *restrict file_hash);
 const zend_string *sp_zval_to_zend_string(const zval *);