lib/dns/dnstap_test:totext does not work well with SoftHSM PKCS11

Summary

dnstap unit test is failing in pkcs11 variant

BIND version used

9.11.5

Steps to reproduce

• ./configure --with-pkcs11 --with-native-pkcs11 --enable-dnstap --with-atf
• make -j4
• cd lib/dns/tests
• export TZ="CET"
• kyua debug dnstap_test:totext

What is the current bug behavior?

Time read from dnstap does not match, because I have different timezone. It produces 96 fails. That is because in case of PKCS11 variant, SoftHSM uses localtime_r at initialization. Normal version is first initialized on the first line.

What is the expected correct behavior?

Environment variable is set before initialization of dns library. Makes no difference.

Relevant configuration files

none

Relevant logs and/or screenshots

# from gdb 
break localtime_r
backtrace

#0  __localtime_r (t=t@entry=0x7fffffffad58, tp=tp@entry=0x7fffffffad70) at localtime.c:29
#1  0x00007ffff48a65d0 in __GI___vsyslog_chk (pri=<optimized out>, flag=1, fmt=0x7ffff3ab87ea "%s%s", 
    ap=ap@entry=0x7fffffffae50) at ../misc/syslog.c:199
#2  0x00007ffff48a6bcf in __syslog_chk (pri=pri@entry=3, flag=flag@entry=1, fmt=fmt@entry=0x7ffff3ab87ea "%s%s")
    at ../misc/syslog.c:129
#3  0x00007ffff3a80988 in syslog (__fmt=0x7ffff3ab87ea "%s%s", __pri=3) at /usr/include/bits/syslog.h:31
#4  softHSMLog (loglevel=loglevel@entry=3, 
    functionName=functionName@entry=0x7ffff3abb3d7 <File::File(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, bool, bool, bool, bool)::__func__> "File", fileName=fileName@entry=0x7ffff3abbc0e "File.cpp", 
    lineNo=lineNo@entry=93, format=format@entry=0x7ffff3abb368 "Could not open the file (%s): %s") at log.cpp:102
#5  0x00007ffff3aa343f in File::File (this=0x7fffffffb340, inPath=..., forRead=<optimized out>, 
    forWrite=<optimized out>, create=<optimized out>, truncate=<optimized out>) at File.cpp:93
#6  0x00007ffff3aa4ed0 in Generation::commit (this=this@entry=0x5555557942b0) at Generation.cpp:144
#7  0x00007ffff3aa5096 in Generation::Generation (this=0x5555557942b0, inPath=..., inIsToken=<optimized out>)
    at Generation.cpp:248
#8  0x00007ffff3aa5114 in Generation::create (
    path="/var/lib/softhsm/tokens//fd04e9e9-bd75-2da1-0e70-82540070b451/generation", isToken=isToken@entry=true)
    at Generation.cpp:40
#9  0x00007ffff3aa8b9b in OSToken::OSToken (this=0x55555575c560, inTokenPath=...) at OSToken.cpp:59
#10 0x00007ffff3aaa38f in OSToken::accessToken (basePath=..., tokenDir=...) at OSToken.cpp:134
#11 0x00007ffff3aa107f in ObjectStore::ObjectStore (this=0x55555575c6c0, inStorePath=...) at ObjectStore.cpp:70
#12 0x00007ffff3a5a9f5 in SoftHSM::C_Initialize (this=0x55555575d610, pInitArgs=<optimized out>) at SoftHSM.cpp:496
#13 0x00007ffff3a42034 in C_Initialize (pInitArgs=0x7ffff799b1e0 <pk11_init_args>) at main.cpp:133
#14 0x00007ffff7735474 in pk11_initialize (mctx=mctx@entry=0x55555575e710, engine=engine@entry=0x0)
    at ../../../lib/isc-pkcs11/pk11.c:209
#15 0x00007ffff7b50022 in dst_lib_init2 (mctx=0x55555575e710, ectx=0x7ffff7f77010, engine=engine@entry=0x0, 
    eflags=eflags@entry=4) at ../../../lib/dns-pkcs11/dst_api.c:199
#16 0x00007ffff7b50219 in dst_lib_init (mctx=<optimized out>, ectx=<optimized out>, eflags=eflags@entry=4)
    at ../../../lib/dns-pkcs11/dst_api.c:149
#17 0x00005555555583f2 in dns_test_begin (logfile=0x0, start_managers=<optimized out>)
    at ../../../../lib/dns-pkcs11/tests/dnstest.c:125
#18 0x0000555555556f92 in atfu_totext_body (tc=<optimized out>) at ../../../../lib/dns-pkcs11/tests/dnstap_test.c:300
#19 0x00007ffff4ec0c69 in atf_tc_run (tc=0x55555575b0c0 <atfu_totext_tc>, resfile=<optimized out>) at atf-c/tc.c:1012
#20 0x00007ffff4ec1a55 in atf_tp_run (tp=tp@entry=0x7fffffffdac0, tcname=<optimized out>, resfile=<optimized out>)
    at atf-c/tp.c:205
#21 0x00007ffff4ec68e4 in run_tc (exitcode=<synthetic pointer>, p=0x7fffffffdae0, tp=0x7fffffffdac0)
    at atf-c/detail/tp_main.c:509
#22 controlled_main (exitcode=<synthetic pointer>, add_tcs_hook=0x5555555576c0 <atfu_tp_add_tcs>, argv=<optimized out>, 
    argc=<optimized out>) at atf-c/detail/tp_main.c:579
---Type <return> to continue, or q <return> to quit---
#23 atf_tp_main (argc=<optimized out>, argv=<optimized out>, add_tcs_hook=0x5555555576c0 <atfu_tp_add_tcs>)
    at atf-c/detail/tp_main.c:609
#24 0x00007ffff47d7fea in __libc_start_main (main=0x555555556e30 <main>, argc=2, argv=0x7fffffffdc68, 
    init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fffffffdc58)
    at ../csu/libc-start.c:308

$ kyua debug dnstap_test:totext
*** Check failed: ../../../../lib/dns-pkcs11/tests/dnstap_test.c:346: (char *) isc_buffer_base(b) != s (03-Feb-2017 23:47:16.000 SQ 10.53.0.1:2112 -> 10.53.0.2:2112 UDP 40b www.isc.org/IN/A != 03-Feb-2017 15:47:16.000 SQ 10.53.0.1:2112 -> 10.53.0.2:2112 UDP 40b www.isc.org/IN/A)
*** Check failed: ../../../../lib/dns-pkcs11/tests/dnstap_test.c:346: (char *) isc_buffer_base(b) != s (04-Feb-2017 00:47:16.830 SQ 10.53.0.1:2112 -> 10.53.0.2:2112 UDP 40b www.isc.org/IN/A != 03-Feb-2017 16:47:16.830 SQ 10.53.0.1:2112 -> 10.53.0.2:2112 UDP 40b www.isc.org/IN/A)
...
*** Check failed: ../../../../lib/dns-pkcs11/tests/dnstap_test.c:346: (char *) isc_buffer_base(b) != s (04-Feb-2017 01:47:16.000 TR 10.53.0.1:2112 <- 10.53.0.2:2112 TCP 287b www.isc.org/IN/A != 03-Feb-2017 17:47:16.000 TR 10.53.0.1:2112 <- 10.53.0.2:2112 TCP 287b www.isc.org/IN/A)
*** Check failed: ../../../../lib/dns-pkcs11/tests/dnstap_test.c:346: (char *) isc_buffer_base(b) != s (04-Feb-2017 00:47:16.830 TR 10.53.0.1:2112 <- 10.53.0.2:2112 TCP 287b www.isc.org/IN/A != 03-Feb-2017 16:47:16.830 TR 10.53.0.1:2112 <- 10.53.0.2:2112 TCP 287b www.isc.org/IN/A)
*** Check failed: ../../../../lib/dns-pkcs11/tests/dnstap_test.c:346: (char *) isc_buffer_base(b) != s (04-Feb-2017 00:47:16.830 TR 10.53.0.1:2112 <- 10.53.0.2:2112 TCP 287b www.isc.org/IN/A != 03-Feb-2017 16:47:16.830 TR 10.53.0.1:2112 <- 10.53.0.2:2112 TCP 287b www.isc.org/IN/A)
dnstap_test:totext  ->  failed: 96 checks failed; see output for more details

Possible fixes

Setenv is called too late.