C Reflection Magic: Simple Logging with A Wrapper for Printing Arbitrary Functions Arguments and Results

This article is a research report which covers some potential implementation aspects of writing a helper wrapper which will automatically log arguments and results of the arbitrary C function. This is one of the examples why reflection may be useful even in C. The implementation is based on the Metac project. The introduction of it was given in this article. The research has some good results, but it still in progress. The comments on how it could be done in a better way are appreciated.

Logging is one of the important ways of debugging. Making proper logging is a key to understanding what potentially went wrong without using a debugger. But it’s annoying to print out all the arguments of each function and its result. C reflection with Metac could potentially have an ability to do this, because debugging information provided by DWARF has all the data about the type of each argument. Check it out. Here is the testing application:

#include <stdio.h>
#include <stdarg.h>
#include <stdlib.h>
#include <string.h>

#include "metac/reflect.h"

int test_function1_with_args(int a, short b) {
    return a + b + 6;
}
METAC_GSYM_LINK(test_function1_with_args);

int main() {
    printf("fn returned: %i\n", test_function1_with_args(1, 2));

    return 0;
}

We want to make some kind of wrapper to print arguments of test_function1_with_args. Metac will generate its reflection info since METAC_GSYM_LINK(test_function1_with_args); is in the code. For simplicity int and short argument types are selected. The first idea how we could create a wrapper is - create a macro:

void print_args(metac_entry_t *p_entry, ...) {
// use va_args and debug information about types to print value of each argument
}

#define METAC_WRAP_FN(_fn_, _args_...) ({ \
        print_args(METAC_GSYM_LINK_ENTRY(_fn_), _args_); \
        _fn_(_args_); \
    })

int main() {
    // use wrapper instead of printf("fn returned: %i\n", test_function1_with_args(1, 2));
    printf("fn returned: %i\n",
        METAC_WRAP_FN(test_function1_with_args, 1, 2));

    return 0;
}

This wrapper so far handles only arguments, but it’s ok for the first step. Lets try to implement print_args. Here is the first naive attempt:

void print_args(metac_entry_t *p_entry, ...) {
    if (p_entry == NULL || metac_entry_has_paremeter(p_entry) == 0) {
        return;
    }

    va_list args;
    va_start(args, p_entry);

    printf("%s(", metac_entry_name(p_entry));

    // output each argument
    for (int i = 0; i < metac_entry_paremeter_count(p_entry); ++i) {
        if (i > 0) {
            printf(", ");
        }

        // get i-th arg
        metac_entry_t * p_param_entry = metac_entry_by_paremeter_id(p_entry, i);
        if (metac_entry_is_parameter(p_param_entry) == 0) {
            // something is wrong
            break;
        }
        // if it’s … argument just print … - there is no way so far to handle that
        if (metac_entry_is_unspecified_parameter(p_param_entry) != 0) {
            // we don't support printing va_args... there is no generic way
            printf("...");
            break;
        }

        // get arg name and info about arg type
        metac_name_t param_name = metac_entry_name(p_param_entry);
        metac_entry_t * p_param_type_entry = metac_entry_parameter_entry(p_param_entry);
        if (param_name == NULL || param_name == NULL) {
            // something is wrong
            break;
        }

        // lets handle only base_types for now
        if (metac_entry_is_base_type(p_param_type_entry) != 0) {
            // take what type of base type it is. It can be char, unsigned char.. etc
            metac_name_t param_base_type_name = metac_entry_base_type_name(p_param_type_entry);

// if _type_ is matching with param_base_type_name, get data using va_arg and print it.
#define _base_type_arg_(_type_, _pseudoname_) \
    do { \
        if (strcmp(param_base_type_name, #_pseudoname_) == 0) { \
            _type_ val = va_arg(args, _type_); \
            metac_value_t * p_val = metac_new_value(p_param_type_entry, &val); \
            if (p_val == NULL) { \
                break; \
            } \
            char * s = metac_value_string(p_val); \
            if (s == NULL) { \
                metac_value_delete(p_val); \
                break; \
            } \
            printf("%s: %s", param_name, s); \
            free(s); \
            metac_value_delete(p_val); \
        } \
    } while(0)
    // handle all known base types
    _base_type_arg_(char, char);
    _base_type_arg_(unsigned char, unsigned char);
    _base_type_arg_(short, short int);
    _base_type_arg_(unsigned short, unsigned short int);
    _base_type_arg_(int, int);
    _base_type_arg_(unsigned int, unsigned int);
    _base_type_arg_(long, long int);
    _base_type_arg_(unsigned long, unsigned long int);
    _base_type_arg_(long long, long long int);
    _base_type_arg_(unsigned long long, unsigned long long int);
    _base_type_arg_(bool, _Bool);
    _base_type_arg_(float, float);
    _base_type_arg_(double, double);
    _base_type_arg_(long double, long double);
    _base_type_arg_(float complex, complex);
    _base_type_arg_(double complex, complex);
    _base_type_arg_(long double complex, complex);
#undef _base_type_arg_
        }
    }
    printf(")\n");
    va_end(args);
    return;
}

If we run it we will see:

% ./c_print_args
test_function1_with_args(a: 1, b: 2)
fn returned: 9

It works! But it handles only base types. And we want it to be universal.

The main challenge here is with this line:

 _type_ val = va_arg(args, _type_); 

C's va_arg macro requires the type of the argument to be known at compile time. However, reflection information only provides type names at runtime. Can we trick it? va_arg is a macros which covers a builtin function. The second parameter is a type (very non-typical thing). But why does this thing at all needs the type? The answer is - to understand the size and to be able to take it from the stack. We need to cover all possible sizes and to get a pointer to the next argument. On Metac side we know the size of argument - we can use this snippet to get it:

        metac_size_t param_byte_sz = 0;
        if (metac_entry_byte_size(p_param_type_entry, &param_byte_sz) != 0) {
            // something is wrong
            break;
        }

As a next idea let's make the macro which will cover 1 size and make sure that we handle it properly:

        char buf[32];
        int handled = 0;
#define _handle_sz_(_sz_) \
        do { \
            if (param_byte_sz == _sz_) { \
                char *x = va_arg(args, char[_sz_]); \
                memcpy(buf, x, _sz_); \
                handled = 1; \
            } \
        } while(0)
        _handle_sz_(1);
        _handle_sz_(2);
        _handle_sz_(3);
        _handle_sz_(4);
// and so on ...
        _handle_sz_(32);
#undef _handle_sz_

With this approach we covered different sizes from 1 to 32. We could generate a code and cover arguments sized till any arbitrary number, but in most cases people use pointers rather than passing arrays/structures directly. For the sake of our example we’ll keep 32.
Lets refactor our function to make it more reusable split it into 2 vprint_args and print_args similarly to ‘vprtintf’ and printf:

void vprint_args(metac_tag_map_t * p_tag_map, metac_entry_t *p_entry, va_list args) {
    if (p_entry == NULL || metac_entry_has_paremeter(p_entry) == 0) {
        return;
    }

    printf("%s(", metac_entry_name(p_entry));

    for (int i = 0; i < metac_entry_paremeter_count(p_entry); ++i) {
        if (i > 0) {
            printf(", ");
        }

        metac_entry_t * p_param_entry = metac_entry_by_paremeter_id(p_entry, i);
        if (metac_entry_is_parameter(p_param_entry) == 0) {
            // something is wrong
            break;
        }
        if (metac_entry_is_unspecified_parameter(p_param_entry) != 0) {
            // we don't support printing va_args... there is no generic way
            printf("...");
            break;
        }

        metac_name_t param_name = metac_entry_name(p_param_entry);
        metac_entry_t * p_param_type_entry = metac_entry_parameter_entry(p_param_entry);
        if (param_name == NULL || p_param_type_entry == NULL) {
            // something is wrong
            break;
        }

        metac_size_t param_byte_sz = 0;
        if (metac_entry_byte_size(p_param_type_entry, &param_byte_sz) != 0) {
            // something is wrong
            break;
        }

        char buf[32];
        int handled = 0;
#define _handle_sz_(_sz_) \
        do { \
            if (param_byte_sz == _sz_) { \
                char *x = va_arg(args, char[_sz_]); \
                memcpy(buf, x, _sz_); \
                handled = 1; \
            } \
        } while(0)
        _handle_sz_(1);
        _handle_sz_(2);
//...
        _handle_sz_(32);
#undef _handle_sz_

        if (handled == 0) {
            break;
        }

        metac_value_t * p_val = metac_new_value(p_param_type_entry, &buf);
        if (p_val == NULL) {
            break;
        }
        char * v = metac_value_string_ex(p_val, METAC_WMODE_deep, p_tag_map);
        if (v == NULL) {
            metac_value_delete(p_val);
            break;
        }
        char * arg_decl = metac_entry_cdecl(p_param_type_entry);
        if (arg_decl == NULL) {
            free(v);
            metac_value_delete(p_val);
            break;
        }

        printf(arg_decl, param_name);
        printf(" = %s", v);

        free(arg_decl);
        free(v);
        metac_value_delete(p_val);

    }
    printf(")");
}

void print_args(metac_tag_map_t * p_tag_map, metac_entry_t *p_entry, ...) {
    va_list args;
    va_start(args, p_entry);
    vprint_args(p_tag_map, p_entry, args);
    va_end(args);
    return;
}

The reader may notice that we added p_tag_map as the first argument. This is for the further research - it's not used in this article.

Lets now try to create a part which handles the result. Unfortunately typeof isn’t supported till C23 (gcc extension as an option, but it won't work with clang) and we have a dilemma - do we want to keep our METAC_WRAP_FN notation as is, or it’s ok to pass it one more argument - type of the function result to be used as a buffer. Probably we could use libffi to handle this in a universal way - Metac knows the type, but it’s not clear how to put the returned data into the buffer of the proper size. For simplicity let’s change our macro:

#define METAC_WRAP_FN_RES(_type_, _fn_, _args_...) ({ \
        printf("calling "); \
        print_args(NULL, METAC_GSYM_LINK_ENTRY(_fn_), _args_); \
        printf("\n"); \
        WITH_METAC_DECLLOC(loc, _type_ res = _fn_(_args_)); \
        print_args_and_res(NULL, METAC_GSYM_LINK_ENTRY(_fn_), METAC_VALUE_FROM_DECLLOC(loc, res), _args_); \
        res; \
    })

Now we’re passing _type_ as a first argument to store the result. If we pass incorrect type or arguments - the compiler will complain about this _type_ res = _fn_(_args_). This is good.
Printing out the result is a trivial task, we already did that in the first article. Let’s also update our test functions to accept some different types of parameters.
Here is the final example code.

If we run it we’ll get with the comments:

% ./c_print_args

# show args of base type arg function
calling test_function1_with_args(int a = 10, short int b = 22)
fn returned: 38

# show args if the first arg is a pointer
calling test_function2_with_args(int * a = (int []){689,}, short int b = 22)
fn returned: 1710

# using METAC_WRAP_FN_RES which will print the result. using pointer to list
calling test_function3_with_args(list_t * p_list = (list_t []){{.x = 42.420000, .p_next = (struct list_s []){{.x = 45.400000, .p_next = NULL,},},},})
fn returned: 87.820000

# another example of METAC_WRAP_FN_RES with int * as a first arg
calling test_function2_with_args(int * a = (int []){689,}, short int b = 22)
test_function2_with_args(int * a = (int []){689,}, short int b = 22) returned 1710

# the log where 1 func with wrapper calls another func with wrapper
calling test_function4_with_args(list_t * p_list = (list_t []){{.x = 42.420000, .p_next = (struct list_s []){{.x = 45.400000, .p_next = NULL,},},},})
calling test_function3_with_args(list_t * p_list = (list_t []){{.x = 42.420000, .p_next = (struct list_s []){{.x = 45.400000, .p_next = NULL,},},},})
test_function3_with_args(list_t * p_list = (list_t []){{.x = 42.420000, .p_next = (struct list_s []){{.x = 45.400000, .p_next = NULL,},},},}) returned 87.820000
test_function4_with_args(list_t * p_list = (list_t []){{.x = 42.420000, .p_next = (struct list_s []){{.x = 45.400000, .p_next = NULL,},},},}) returned -912.180000

It’s seen that Metac prints for us the deep representation of the arguments as well as results. In general it works, though there are some flaws like a need to handle each size of argument separately.

Here are some additional limitations:

1. clang doesn't expose debug information about external functions like printf. That means - our wrapper won't work with that as-is. We may need to introduce some additional tricks.
2. functions with unspecified arguments ... won't show such arguments. there is no generic way, but potentially we may want to give a way to provide a callback to extract information for such cases.
3. there is no (yet?) support for the cases of linked arguments, e.g. when we pass pointer and length as 2 separate but logically connected arguments .

If you have any suggestion on how it could be more generic - please comment. Thanks for reading!