test: introduce core_log() unit tests

[janekmi]

This change is 

[grom72]

Reviewed 3 of 6 files at r1, all commit messages.
Reviewable status: 3 of 6 files reviewed, 13 unresolved discussions (waiting on @janekmi)

---

src/test/core_log/core_log.c line 17 at r1 (raw file):

#define FILE_NAME "dummy.c"
#define LINE_NO 123

To use as many characters as real files can report.

Suggestion:

#define LINE_NO 1234

---

src/test/core_log/core_log.c line 22 at r1 (raw file):

#define DUMMY_ARG 456
#define LAST_ERROR_MSG_MOCK ((char *)0x1a547e58)
#define ANYTHING_BUT_LAST_ERROR_MSG ((char *)0xa7481768)

There is a relation between them and this relationship is hard to deduct from names.

Suggestion:

#define ANYTHING_BUT_LAST_ERROR_MSG ((char *)LAST_ERROR_MSG_MOCK << 2)

---

src/test/core_log/core_log.c line 25 at r1 (raw file):

#define DUMMY_CONTEXT ((void *)0x800df00d)
#define DUMMY_ERRNO1 500
#define DUMMY_ERRNO2 313

Do we need the second errno?

Code quote:

DUMMY_ERRNO2

---

src/test/core_log/core_log.c line 48 at r1 (raw file):

} Vsnprintf_ = {
	.use_mock = false
};

static bool is initialized to 0 (false).

Suggestion:

} Vsnprintf_;

---

src/test/core_log/core_log.c line 60 at r1 (raw file):

	 * framework relies on it to work as normal.
	 */
	Vsnprintf_.use_mock = false;

This logic can be implemented easily with

FUNC_MOCK_RUN(0) {
 if(Vsnprintf_.use_mock) {
	if (Common.exp_buf == ANYTHING_BUT_LAST_ERROR_MSG) {
		UT_ASSERTne(__s, LAST_ERROR_MSG_MOCK);
	} else {
		UT_ASSERTeq(__s, Common.exp_buf);
	}
        .....
}
FUNC_MOCK_RUN_DEFAULT {
		return _FUNC_REAL(vsnprintf)(__s, __maxlen, __format, __arg);
}

Code quote:

FUNC_MOCK_RUN_DEFAULT {
	if (!Vsnprintf_.use_mock) {
		return _FUNC_REAL(vsnprintf)(__s, __maxlen, __format, __arg);
	}
	/*
	 * Have to arm this fuse ASAP since all the output from the unittest
	 * framework relies on it to work as normal.
	 */
	Vsnprintf_.use_mock = false;

---

src/test/core_log/core_log.c line 66 at r1 (raw file):

	} else {
		UT_ASSERTeq(__s, Common.exp_buf);
	}

Very difficult to follow this logic

Code quote:

	if (Common.exp_buf == ANYTHING_BUT_LAST_ERROR_MSG) {
		UT_ASSERTne(__s, LAST_ERROR_MSG_MOCK);
	} else {
		UT_ASSERTeq(__s, Common.exp_buf);
	}

---

src/test/core_log/core_log.c line 96 at r1 (raw file):

	} else {
		return Strerror_r.error;
	}

else after return does not increase clarity

Suggestion:

	if (Strerror_r.error == EXIT_SUCCESS)
		return 0;
	if (Strerror_r.before_glibc_2_13) {
		errno = Strerror_r.error;
		return -1;
	}
	return Strerror_r.error;
	

---

src/test/core_log/core_log.c line 106 at r1 (raw file):

} Log_function_ = {
	.use_mock = false
};

static bool is initialized to 0 (false).

Suggestion:

} Log_function_;

---

src/test/core_log/core_log.c line 110 at r1 (raw file):

static void
log_function(void *context, enum core_log_level level, const char *file_name,
	const int line_no, const char *function_name, const char *message)

Why do you use custom log_function instead of mocking the default one?

Code quote:

static void
log_function(void *context, enum core_log_level level, const char *file_name,
	const int line_no, const char *function_name, const char *message)

---

src/test/core_log/core_log.c line 136 at r1 (raw file):

static void
reset_call_counters(void)

I know we reset only counters but practically we somehow reset mocks

Suggestion:

reset_mocks

---

src/test/core_log/core_log.c line 163 at r1 (raw file):

	Vsnprintf_.use_mock = true;
	Vsnprintf_.ret = 0; /* empty but successful */
	Log_function_.exp_level = CORE_LOG_LEVEL_ERROR;

Would it be better to use the same level in core_log_set_threshold and in core_log?

Suggestion:

CORE_LOG_LEVEL_DEBUG

---

src/test/core_log/core_log.c line 256 at r1 (raw file):

	UT_ASSERTeq(RCOUNTER(__xpg_strerror_r), 0);
	UT_ASSERTeq(Log_function_.rcounter, 1);
}

Suggestion:

	UT_ASSERTeq(Log_function_.rcounter, 1);
	
	return NO_ARGS_CONSUMED;
}

---

src/test/core_log/core_log.c line 388 at r1 (raw file):

	 * the default log function instead. Hence, the direct assignment.
	 */
	Core_log_function = 0;

I wonder why Core_log_function is public.

Code quote:

Core_log_function = 0;

[janekmi]

Reviewed 1 of 6 files at r1, 12 of 12 files at r2, 12 of 12 files at r4, all commit messages.
Reviewable status: all files reviewed, 13 unresolved discussions (waiting on @grom72)

---

src/test/core_log/core_log.c line 17 at r1 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

To use as many characters as real files can report.

Done.

---

src/test/core_log/core_log.c line 22 at r1 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

There is a relation between them and this relationship is hard to deduct from names.

Done.

---

src/test/core_log/core_log.c line 25 at r1 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

Do we need the second errno?

I would prefer different things differentiable.

---

src/test/core_log/core_log.c line 48 at r1 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

static bool is initialized to 0 (false).

Done.

---

src/test/core_log/core_log.c line 60 at r1 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

This logic can be implemented easily with

FUNC_MOCK_RUN(0) {
 if(Vsnprintf_.use_mock) {
	if (Common.exp_buf == ANYTHING_BUT_LAST_ERROR_MSG) {
		UT_ASSERTne(__s, LAST_ERROR_MSG_MOCK);
	} else {
		UT_ASSERTeq(__s, Common.exp_buf);
	}
        .....
}
FUNC_MOCK_RUN_DEFAULT {
		return _FUNC_REAL(vsnprintf)(__s, __maxlen, __format, __arg);
}

Done.

---

src/test/core_log/core_log.c line 66 at r1 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

Very difficult to follow this logic

Done.

---

src/test/core_log/core_log.c line 96 at r1 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

else after return does not increase clarity

There are two ways in which this function can fail. I can not think of a more clear way of doing that than if-else. 🥊

---

src/test/core_log/core_log.c line 106 at r1 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

static bool is initialized to 0 (false).

Done.

---

src/test/core_log/core_log.c line 110 at r1 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

Why do you use custom log_function instead of mocking the default one?

Done.

---

src/test/core_log/core_log.c line 136 at r1 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

I know we reset only counters but practically we somehow reset mocks

Done.

---

src/test/core_log/core_log.c line 163 at r1 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

Would it be better to use the same level in core_log_set_threshold and in core_log?

Done.

---

src/test/core_log/core_log.c line 256 at r1 (raw file):

	UT_ASSERTeq(RCOUNTER(__xpg_strerror_r), 0);
	UT_ASSERTeq(Log_function_.rcounter, 1);
}

No. It is just a void helper.

---

src/test/core_log/core_log.c line 388 at r1 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

I wonder why Core_log_function is public.

Done.

[grom72]

Reviewed 2 of 6 files at r1, 2 of 12 files at r3, 12 of 12 files at r4, all commit messages.
Reviewable status: all files reviewed, 12 unresolved discussions (waiting on @janekmi and @osalyk)

a discussion (no related file):
I think we do not need a separate core_log_no_func.c. We need only a separate main() for this case or just conditionally include this section:

#ifdef NO_LOG_FUNCTION
#undef LOG_SET_PMEMCORE_FUNC
#define LOG_SET_PMEMCORE_FUNC
#ENDIF

before main and separate Makefile and Test files.
With such modification we avoid core_log_common.c and all related to that complexity of the solution.

---

---

src/test/core_log/core_log.c line 38 at r4 (raw file):

	core_log(CORE_LOG_LEVEL_ERROR_LAST, NO_ERRNO, FILE_NAME, LINE_NO,
		FUNC_NAME, MSG_FORMAT, DUMMY_ARG);

It is a tricky part.
MSG_FORMAT does not indicate any expected arguments, but we pass something (?).

Code quote:

MSG_FORMAT, DUMMY_ARG

---

src/test/core_log/core_log_common.c line 36 at r4 (raw file):

			UT_ASSERTeq(__maxlen, _CORE_LOG_MSG_MAXPRINT);
		}
		UT_ASSERTstreq(__format, MSG_FORMAT);

Why do we use real, but "dummy", string instead of mock?

Code quote:

		UT_ASSERTstreq(__format, MSG_FORMAT)

---

src/test/core_log/core_log_common.c line 107 at r4 (raw file):

	Common.use_last_error_msg = false;

	reset_mocks();

It will be more natural to reset_mocks() first and next adjust their behavior/expectation.

Code quote:

	/* set the expectations */
	Vsnprintf_.ret = core_message_length;
	Log_function_.exp_level = CORE_LOG_LEVEL_ERROR;
	Common.use_last_error_msg = false;

	reset_mocks();

---

src/test/core_log/Makefile line 14 at r4 (raw file):

include ../Makefile.inc
LDFLAGS += $(call extract_funcs, core_log_common.c)

It is common for all core_log tests -> ../core_log/Makefile.inc?

Code quote:

BUILD_STATIC_DEBUG=n
BUILD_STATIC_NONDEBUG=n

# `internal` is required for proper mock integration
LIBPMEMCORE=internal-debug

include ../Makefile.inc
LDFLAGS += $(call extract_funcs, core_log_common.c)

---

src/test/core_log/TESTS.py line 12 at r3 (raw file):

@g.require_granularity(g.ANY)
@t.require_build('nondebug')  # XXX ANY

nondebug or debug? We use internal-debug in Makefile
Not ANY as we know that it does not work with static-

Code quote:

@t.require_build('nondebug')  # XXX ANY

---

src/test/core_log_no_func/core_log_no_func.c line 29 at r4 (raw file):

	bool call_log_function = false;

	test_log_function_call_helper(CORE_LOG_LEVEL_ERROR, call_log_function);

or rename this variable to log_function_called, but anyhow there is more value in checking what false means for test_log_function_call_helper instead of building additional semantics here.

Suggestion:

	test_log_function_call_helper(CORE_LOG_LEVEL_ERROR, false);

---

src/test/core_log_no_func/core_log_no_func.c line 29 at r4 (raw file):

	bool call_log_function = false;

	test_log_function_call_helper(CORE_LOG_LEVEL_ERROR, call_log_function);

Shall we also check this for CORE_LOG_LEVEL_ERROE_LAST + check that last_error_msg is used properly?

Code quote:

test_log_function_call_helper(CORE_LOG_LEVEL_ERROR, call_log_function);

---

src/test/core_log_no_func/core_log_no_func.c line 42 at r4 (raw file):

int
main(int argc, char *argv[])
{

Otherwise, ut_log_function is called all the time.

Suggestion:

#undef LOG_SET_PMEMCORE_FUNC
#define LOG_SET_PMEMCORE_FUNC

int
main(int argc, char *argv[])
{

---

src/test/core_log_no_func/Makefile line 15 at r4 (raw file):

include ../Makefile.inc
LDFLAGS += $(call extract_funcs, ../core_log/core_log_common.c)
INCS += -I../core_log

Would it be better to move this part to ../core_log/Makefile.inc and include it here?

Code quote:

BUILD_STATIC_DEBUG=n
BUILD_STATIC_NONDEBUG=n

# `internal` is required for proper mock integration
LIBPMEMCORE=internal-debug

include ../Makefile.inc
LDFLAGS += $(call extract_funcs, ../core_log/core_log_common.c)
INCS += -I../core_log

---

src/test/core_log_no_func/TESTS.py line 12 at r4 (raw file):

@g.require_granularity(g.ANY)
@t.require_build('nondebug')  # XXX ANY

Suggestion:

@t.require_build('nondebug')

---

src/test/unittest/unittest.h line 549 at r4 (raw file):

#define FUNC_MOCK(name, ret_type, ...)\
	_FUNC_REAL_DECL(name, ret_type, ##__VA_ARGS__)\
	static unsigned RCOUNTER(name);\

Do we understand all the consequences of this change?
We can avoid this if we either move all mocks definitions to core_log_common.h or/and convert all *-helpers to macros.

[janekmi]

Reviewable status: all files reviewed, 12 unresolved discussions (waiting on @grom72 and @osalyk)

a discussion (no related file):

Previously, grom72 (Tomasz Gromadzki) wrote…

I think we do not need a separate core_log_no_func.c. We need only a separate main() for this case or just conditionally include this section:

#ifdef NO_LOG_FUNCTION
#undef LOG_SET_PMEMCORE_FUNC
#define LOG_SET_PMEMCORE_FUNC
#ENDIF

before main and separate Makefile and Test files.
With such modification we avoid core_log_common.c and all related to that complexity of the solution.

It would require:

1. An overarching #ifndef NO_LOG_FUNCTION ... #else ... #endif /* NO_LOG_FUNCTION */ maybe even a few of them in order to make a compilable file with and without the define.
2. A separate directory for both binaries and dedicated Makefile and TEST.py won't go away in this case.

Are you ok with this?

---

---

src/test/core_log/core_log.c line 38 at r4 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

It is a tricky part.
MSG_FORMAT does not indicate any expected arguments, but we pass something (?).

An actual format is necessary only when you have no other way of knowing what variadic arguments you can expect. We are leveraging another way. The mock MSG_FORMAT is not fed into any real function which may attempt to consume it. Hence, we can get away with mocking it all the way and checking whether at least a single variadic argument can be passed.

Otherwise, we cannot assess this part of the interface at all.

---

src/test/core_log/core_log_common.c line 36 at r4 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

Why do we use real, but "dummy", string instead of mock?

What "real" vs what "dummy"? We check whether the passed format went through unchanged.
Can you elaborate on what your concern is with this check?

---

src/test/core_log/Makefile line 14 at r4 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

It is common for all core_log tests -> ../core_log/Makefile.inc?

Please. Don't force me to replicate this antipattern. 😝
But let's pretend we argue reasonably:

1. Little value.
2. It will be tricky since the other directory needs other paths.
3. Unprecedented.

---

src/test/core_log/TESTS.py line 12 at r3 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

nondebug or debug? We use internal-debug in Makefile
Not ANY as we know that it does not work with static-

This require_build() is confusing. It does not apply to the process of building the test binary but rather to the source of dynamic libraries (a path to be exact) provided at runtime.

internal-debug is necessary when we build the binary because:

• internal allows us to mock some core functions.
• debug is necessary because nondebug does not provide the out_log() necessary for the unittest/*.

Here ANY would be ideal since this particular unit test sincerely does not care. It does not link with any dynamic library anyways.

---

src/test/core_log_no_func/Makefile line 15 at r4 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

Would it be better to move this part to ../core_log/Makefile.inc and include it here?

🤮

---

src/test/core_log_no_func/TESTS.py line 12 at r4 (raw file):

@g.require_granularity(g.ANY)
@t.require_build('nondebug')  # XXX ANY

Considering the confusion, I argue this comment should be even extended. I will propose something when we settle on how we would like to have these two binaries built.

---

src/test/unittest/unittest.h line 549 at r4 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

Do we understand all the consequences of this change?
We can avoid this if we either move all mocks definitions to core_log_common.h or/and convert all *-helpers to macros.

1. No consequences as far as I am concerned. It only means the variable can be accessed outside its original compilation unit.
2. We cannot move the definition to a header file since it will result in creating an instance in each of the compilation units including the common header. It does not solve the issue of having access to the same variable from more than one compilation unit.
3. I have enough macros for quite some time and you will have to find a really good argument to convince me to use one. Especially, the existing function-based implementation so far is fit for the purpose.

Ref: https://en.wikipedia.org/wiki/Static_(keyword)#Static_global_variable

[janekmi]

Reviewable status: all files reviewed, 12 unresolved discussions (waiting on @grom72 and @osalyk)

a discussion (no related file):

Previously, janekmi (Jan Michalski) wrote…

It would require:

1. An overarching #ifndef NO_LOG_FUNCTION ... #else ... #endif /* NO_LOG_FUNCTION */ maybe even a few of them in order to make a compilable file with and without the define.
2. A separate directory for both binaries and dedicated Makefile and TEST.py won't go away in this case.

Are you ok with this?

Here you can preview how it could look like: https://github.com/janekmi/pmdk/tree/core_log-ut-alt

IMHO it looks nasty: https://github.com/janekmi/pmdk/blob/core_log-ut-alt/src/test/core_log/core_log.c. The core_log.c and core_log_no_func.c have basically no common points.

The common bits are in core_log_common.c/.h and if we decide to go that way they will end up in the core_log.c as well. But not just as a nice and simple copy-paste but again as pieces of code lying in the same source file but turned on and off by the define.

The key issue is that most of the code won't be used when NO_LOG_FUNCTION is defined. So we have to exclude it from the compilation (note that unused is a build error). At the same time, what remains uses just bits and pieces from the bulk of definitions existed so far hence we end up with a nasty-looking ifdef-else-endif salad.

---

[janekmi]

Reviewed 1 of 6 files at r1, 11 of 11 files at r5, all commit messages.
Reviewable status: all files reviewed, 7 unresolved discussions (waiting on @grom72 and @osalyk)

---

src/test/core_log/core_log.c line 38 at r4 (raw file):

Previously, janekmi (Jan Michalski) wrote…

An actual format is necessary only when you have no other way of knowing what variadic arguments you can expect. We are leveraging another way. The mock MSG_FORMAT is not fed into any real function which may attempt to consume it. Hence, we can get away with mocking it all the way and checking whether at least a single variadic argument can be passed.

Otherwise, we cannot assess this part of the interface at all.

Done.

---

src/test/core_log/core_log_common.c line 36 at r4 (raw file):

Previously, janekmi (Jan Michalski) wrote…

What "real" vs what "dummy"? We check whether the passed format went through unchanged.
Can you elaborate on what your concern is with this check?

Done.

---

src/test/core_log/TESTS.py line 12 at r3 (raw file):

Previously, janekmi (Jan Michalski) wrote…

This require_build() is confusing. It does not apply to the process of building the test binary but rather to the source of dynamic libraries (a path to be exact) provided at runtime.

internal-debug is necessary when we build the binary because:

• internal allows us to mock some core functions.
• debug is necessary because nondebug does not provide the out_log() necessary for the unittest/*.

Here ANY would be ideal since this particular unit test sincerely does not care. It does not link with any dynamic library anyways.

Done.

---

src/test/core_log_no_func/core_log_no_func.c line 29 at r4 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

or rename this variable to log_function_called, but anyhow there is more value in checking what false means for test_log_function_call_helper instead of building additional semantics here.

Done.

---

src/test/core_log_no_func/core_log_no_func.c line 29 at r4 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

Shall we also check this for CORE_LOG_LEVEL_ERROE_LAST + check that last_error_msg is used properly?

Done.

---

src/test/core_log_no_func/core_log_no_func.c line 42 at r4 (raw file):

Previously, grom72 (Tomasz Gromadzki) wrote…

Otherwise, ut_log_function is called all the time.

Done.

---

src/test/core_log_no_func/TESTS.py line 12 at r4 (raw file):

Previously, janekmi (Jan Michalski) wrote…

Considering the confusion, I argue this comment should be even extended. I will propose something when we settle on how we would like to have these two binaries built.

Done.

[grom72]

🐐

Reviewed 11 of 11 files at r5, all commit messages.
Reviewable status: all files reviewed, 2 unresolved discussions (waiting on @janekmi and @osalyk)

---

src/test/core_log/TESTS.py line 14 at r5 (raw file):

# once. No dynamic libraries are used nor .static_* builds are available.
@g.require_granularity(g.ANY)
@t.require_build('nondebug')

Suggestion:

@g.require_granularity(g.ANY)
# The 'nondebug' build is chosen arbitrarily to ensure these tests are run only
# once. No dynamic libraries are used nor .static_* builds are available.
@t.require_build('nondebug')

---

src/test/core_log_no_func/TESTS.py line 14 at r5 (raw file):

# once. No dynamic libraries are used nor .static_* builds are available.
@g.require_granularity(g.ANY)
@t.require_build('nondebug')

Suggestion:

@g.require_granularity(g.ANY)
# The 'nondebug' build is chosen arbitrarily to ensure these tests are run only
# once. No dynamic libraries are used nor .static_* builds are available.
@t.require_build('nondebug')

[janekmi]

Reviewed 2 of 2 files at r6, all commit messages.
Reviewable status: complete! all files reviewed, all discussions resolved (waiting on @osalyk)

[grom72]

Reviewable status: complete! all files reviewed, all discussions resolved (waiting on @osalyk)

[osalyk]

Reviewed 3 of 6 files at r1, 4 of 12 files at r4, 9 of 11 files at r5, 2 of 2 files at r6, 1 of 1 files at r7, all commit messages.
Reviewable status: complete! all files reviewed, all discussions resolved (waiting on @janekmi)