unit heaptrc does not write its report when STDERR is redirected
lazarus / 64-FPC development

----------------------------------------------------------------------
bodo-hugo-barwich · 2020-10-22 21:56

Coming from this issue:
Memory Leak in fptest Unit
I found that the Unit heaptrc does not write its report when the
STDERR is redirected.

The normal behaviour is that heaptrc write its report to STDERR
as seen in this strace log:

$ strace -f -o strace_demo_2020-10-22-2.log ./demo_hash-lists.run
Key: 'gob': 'gob_value'
Key: 'bog': 'bog_value'
Key: 'bob': ''
hsh map (cnt: '2'):
str map 'es' (cnt: '4'):
; key: 'key6' => 'value6'; key: 'bog' => 'bog_value'; key: 'gob' =>
'gob_value'; key: 'trying a somwhat very long key 1' => 'inserting
it's somewhat very long value 1'
str map 'en' (cnt: '3'):
; key: 'ab' => 'cd'; key: 'ij' => 'kl'; key: 'ef' => 'gh'
Heap dump by heaptrc unit
66 memory blocks allocated : 3144/3168
66 memory blocks freed     : 3144/3168
0 unfreed memory blocks : 0
True heap size : 131072
True free heap : 131072

produces this strace activity log:

$ grep -ni "" strace_demo_2020-10-22-2.log
1:2581  execve("./demo_hash-lists.run", ["./demo_hash-lists.run"],
0x7ffd15c72448 /* 46 vars */) = 0
2:2581  getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024,
rlim_max=RLIM64_INFINITY}) = 0
3:2581  rt_sigaction(SIGFPE, {sa_handler=0x4244e0, sa_mask=[],
sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x4026b0},
{sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8 ) = 0
4:2581  rt_sigaction(SIGSEGV, {sa_handler=0x4244e0, sa_mask=[],
sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x4026b0},
{sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8 ) = 0
5:2581  rt_sigaction(SIGBUS, {sa_handler=0x4244e0, sa_mask=[],
sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x4026b0},
{sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8 ) = 0
6:2581  rt_sigaction(SIGILL, {sa_handler=0x4244e0, sa_mask=[],
sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x4026b0},
{sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8 ) = 0
7:2581  ioctl(1, TCGETS, {B38400 opost isig icanon echo ...}) = 0
8:2581  ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
9:2581  ioctl(1, TCGETS, {B38400 opost isig icanon echo ...}) = 0
10:2581  ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
11:2581  readlink("/proc/self/exe",
"/home/bodo/Projekte/pascal/hash-"..., 255) = 57
12:2581  open("/etc/timezone", O_RDONLY|O_LARGEFILE) = 3
13:2581  read(3, "Atlantic/Canary\n", 255) = 16
14:2581  close(3)                          = 0
15:2581  open("/usr/share/zoneinfo/Atlantic/Canary",
O_RDONLY|O_LARGEFILE) = 3
16:2581  read(3,
"TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\6\0\0\0\6\0\0\0\0"...,
2048) = 1911
17:2581  mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfdaefe000
18:2581  mmap(NULL, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfdaef6000
19:2581  mmap(NULL, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfdaeee000
20:2581  close(3)                          = 0
21:2581  time([1603402165 /* 2020-10-22T22:29:25+0100 */]) =
1603402165 (2020-10-22T22:29:25+0100)
22:2581  mmap(NULL, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfdaee6000
23:2581  mmap(NULL, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfdaede000
24:2581  mmap(NULL, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfdaed6000
25:2581  mmap(NULL, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfdaece000
26:2581  write(1, "Key: 'gob': '", 13)     = 13
27:2581  write(1, "gob_value", 9)          = 9
28:2581  write(1, "'\n", 2)                = 2
29:2581  write(1, "Key: 'bog': '", 13)     = 13
30:2581  write(1, "bog_value", 9)          = 9
31:2581  write(1, "'\n", 2)                = 2
32:2581  write(1, "Key: 'bob': '", 13)     = 13
33:2581  write(1, "'\n", 2)                = 2
34:2581  write(1, "hsh map (cnt: '2'):\n", 20) = 20
35:2581  write(1, "str map 'es' (cnt: '4'):\n", 25) = 25
36:2581  write(1, "; key: 'key6' => 'value6'", 25) = 25
37:2581  write(1, "; key: 'bog' => 'bog_value'", 27) = 27
38:2581  write(1, "; key: 'gob' => 'gob_value'", 27) = 27
39:2581  write(1, "; key: 'trying a somwhat very lo"..., 88) = 88
40:2581  write(1, "\n", 1)                 = 1
41:2581  write(1, "str map 'en' (cnt: '3'):\n", 25) = 25
42:2581  write(1, "; key: 'ab' => 'cd'", 19) = 19
43:2581  write(1, "; key: 'ij' => 'kl'", 19) = 19
44:2581  write(1, "; key: 'ef' => 'gh'", 19) = 19
45:2581  write(1, "\n", 1)                 = 1
46:2581  munmap(0x7fcfdaefe000, 262144)    = 0
47:2581  munmap(0x7fcfdaef6000, 32768)     = 0
48:2581  munmap(0x7fcfdaeee000, 32768)     = 0
49:2581  write(2, "Heap dump by heaptrc unit\n", 26) = 26
50:2581  write(2, "66 memory blocks allocated : 314"..., 39) = 39
51:2581  write(2, "66 memory blocks freed     : 314"..., 39) = 39
52:2581  write(2, "0 unfreed memory blocks : 0\n", 28) = 28
53:2581  write(2, "True heap size : 131072", 23) = 23
54:2581  write(2, "\n", 1)                 = 1
55:2581  write(2, "True free heap : 131072\n", 24) = 24
56:2581  munmap(0x7fcfdaee6000, 32768)     = 0
57:2581  munmap(0x7fcfdaede000, 32768)     = 0
58:2581  munmap(0x7fcfdaed6000, 32768)     = 0
59:2581  munmap(0x7fcfdaece000, 32768)     = 0
60:2581  exit_group(0)                     = ?
61:2581  +++ exited with 0 +++

Between lines 49 - 54 it shows that the Report is written to STDERR

Now redirecting the STDERR this whole section is missing:

$ strace -f -o strace_demo_2020-10-22-1.log ./demo_hash-lists.run
2>demo_error.log 1>demo_report.log
$ grep -ni "" strace_demo_2020-10-22-1.log
1:2566  execve("./demo_hash-lists.run", ["./demo_hash-lists.run"],
0x7fffb7d8b7d8 /* 46 vars */) = 0
2:2566  getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024,
rlim_max=RLIM64_INFINITY}) = 0
3:2566  rt_sigaction(SIGFPE, {sa_handler=0x4244e0, sa_mask=[],
sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x4026b0},
{sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8 ) = 0
4:2566  rt_sigaction(SIGSEGV, {sa_handler=0x4244e0, sa_mask=[],
sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x4026b0},
{sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8 ) = 0
5:2566  rt_sigaction(SIGBUS, {sa_handler=0x4244e0, sa_mask=[],
sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x4026b0},
{sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8 ) = 0
6:2566  rt_sigaction(SIGILL, {sa_handler=0x4244e0, sa_mask=[],
sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x4026b0},
{sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8 ) = 0
7:2566  ioctl(1, TCGETS, 0x7fffb4bf5f80)  = -1 ENOTTY (Función ioctl
no apropiada para el dispositivo)
8:2566  ioctl(2, TCGETS, 0x7fffb4bf5f80)  = -1 ENOTTY (Función ioctl
no apropiada para el dispositivo)
9:2566  ioctl(1, TCGETS, 0x7fffb4bf5f80)  = -1 ENOTTY (Función ioctl
no apropiada para el dispositivo)
10:2566  ioctl(2, TCGETS, 0x7fffb4bf5f80)  = -1 ENOTTY (Función ioctl
no apropiada para el dispositivo)
11:2566  readlink("/proc/self/exe",
"/home/bodo/Projekte/pascal/hash-"..., 255) = 57
12:2566  open("/etc/timezone", O_RDONLY|O_LARGEFILE) = 3
13:2566  read(3, "Atlantic/Canary\n", 255) = 16
14:2566  close(3)                          = 0
15:2566  open("/usr/share/zoneinfo/Atlantic/Canary",
O_RDONLY|O_LARGEFILE) = 3
16:2566  read(3,
"TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\6\0\0\0\6\0\0\0\0"...,
2048) = 1911
17:2566  mmap(NULL, 262144, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f15d6986000
18:2566  mmap(NULL, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f15d697e000
19:2566  mmap(NULL, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f15d6976000
20:2566  close(3)                          = 0
21:2566  time([1603401977 /* 2020-10-22T22:26:17+0100 */]) =
1603401977 (2020-10-22T22:26:17+0100)
22:2566  mmap(NULL, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f15d696e000
23:2566  mmap(NULL, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f15d6966000
24:2566  mmap(NULL, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f15d695e000
25:2566  mmap(NULL, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f15d6956000
26:2566  write(1, "Key: 'gob': 'gob_value'\nKey: 'bo"..., 256) = 256
27:2566  write(1, " very long value 1'\nstr map 'en'"..., 103) = 103
28:2566  munmap(0x7f15d6986000, 262144)    = 0
29:2566  munmap(0x7f15d697e000, 32768)     = 0
30:2566  munmap(0x7f15d6976000, 32768)     = 0
31:2566  munmap(0x7f15d696e000, 32768)     = 0
32:2566  munmap(0x7f15d6966000, 32768)     = 0
33:2566  munmap(0x7f15d695e000, 32768)     = 0
34:2566  munmap(0x7f15d6956000, 32768)     = 0
35:2566  exit_group(0)                     = ?
36:2566  +++ exited with 0 +++

Between lines 31 and 32 the heaptrc is expected but it simply does not
happen.

This issue is especially relevant because it hinders any use of
heaptrc in any reliable CI pipeline.

I like this feature very much because it helps to develop solid and
reliable applications. I would not like just to disable it because the
code quality would suffer.

----------------------------------------------------------------------
bodo-hugo-barwich · 2020-11-15 18:33

I figured out a Workaround which works quite nice.
According to the HeapTrc at:
HeapTrc Environment Variables
Code: Text  [Select][+][-]window.onload = function(){var x1 =
document.getElementById("main_content_section"); if (x1) { var x =
document.getElementsByClassName("geshi");for (var i = 0; i          
#Execute the Demo Application          echo "Demo Application:
Executing ..."          export HEAPTRC="log=demo_heap.log";
./demo_hash-lists.dbg.run 2>./demo_error.log 1>./demo_exec.log ;
error_code=$?          echo "Demo Application: Execution finished with
[$error_code]"          #Demo Application Execution Report         
echo "Demo Execution Log:" ; cat ./demo_exec.log          echo "Demo
Execution Error:" ; cat ./demo_error.log          echo "Demo Execution
Heap:" ; cat ./demo_heap.log          error=`cat ./demo_error.log` ;
if [ -n "$error" ]; then echo "Demo failed with Error [Code:
'$error_code']" && exit 1; fi ;          leak=`cat ./demo_heap.log |
grep -i "unfreed memory blocks" | awk '{print $1}'` ; if [ $leak -ne 0
]; then echo "Memory Leaks: $leak" && exit 1; else echo "Memory Leaks:
NONE"; fi ; 
This enables me to check for Memory Leaks and possible Execution
Errors while nicely documenting the Test Suite Execution.

This produces a nice Report:
GitHub Workflow Report

Demo Application: Executing ...
Demo Application: Execution finished with [ 0 ]
Demo Execution Log:
Key: 'gob': 'gob_value'
Key: 'bog': 'bog_value'
Key: 'bob': ''
hsh map (cnt: '2'):
str map 'es' (cnt: '4'):
; key: 'key6' => 'value6'; key: 'bog' => 'bog_value'; key: 'gob' =>
'gob_value'; key: 'trying a somwhat very long key 1' => 'inserting its
somewhat very long value 1'
str map 'en' (cnt: '3'):
; key: 'ab' => 'cd'; key: 'ij' => 'kl'; key: 'ef' => 'gh'
Demo Execution Error:
Demo Execution Heap:
/home/runner/work/hash-lists/hash-lists/demo_hash-lists.dbg.run
Heap dump by heaptrc unit
68 memory blocks allocated : 2662/2688
68 memory blocks freed     : 2662/2688
0 unfreed memory blocks : 0
True heap size : 163840
True free heap : 163840
Memory Leaks: NONE
Application Tests: Executing ...
Application Tests: Tests finished with [ 0 ]
Tests Execution Log:

FPTest / Testing
.......
Time: 00:00:00.001


OK: 7 tests

Tests Execution Error:
Tests Execution Heap:
/home/runner/work/hash-lists/hash-lists/tests/tests_hash-lists.dbg.run
Heap dump by heaptrc unit
636 memory blocks allocated : 31619/32944
635 memory blocks freed     : 31611/32936
1 unfreed memory blocks : 8
True heap size : 458752
True free heap : 458592
Should be : 458616
Call trace for block $00007F6DCD6912A0 size 8
  $00000000004ADB11 line 2258 of ../fptest/src/TestFramework.pas
  $00000000004B19FF line 2705 of ../fptest/src/TestFramework.pas
  $00000000004B0B46 line 2808 of ../fptest/src/TestFramework.pas
  $00000000004B1222 line 2741 of ../fptest/src/TestFramework.pas
  $00000000004B0B7F line 2810 of ../fptest/src/TestFramework.pas
  $00000000004B986B line 3829 of ../fptest/src/TestFramework.pas
  $000000000049A7C4 line 899 of ../fptest/src/TestFrameworkProxy.pas
  $0000000000496DBF line 322 of ../fptest/src/TestFrameworkProxy.pas
Memory Leaks: NONE


I needed to ignore the Memory Leak in the fptest Unit but if this
increases the Automated Tests will tell me right away.