Lazarus

Free Pascal => FPC development => Topic started by: bodo-hugo-barwich on October 22, 2020, 11:56:30 pm

Title: unit heaptrc does not write its report when STDERR is redirected
Post by: bodo-hugo-barwich on October 22, 2020, 11:56:30 pm

Coming from this issue:
Memory Leak in fptest Unit (https://forum.lazarus.freepascal.org/index.php/topic,51814.msg381003.html#msg381003)
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.

Title: Re: unit heaptrc does not write its report when STDERR is redirected
Post by: bodo-hugo-barwich on November 15, 2020, 07:33:19 pm

I figured out a Workaround which works quite nice.
According to the HeapTrc at:
HeapTrc Environment Variables (https://www.freepascal.org/docs-html/rtl/heaptrc/environment.html)

Code: Text  [Select][+][-]

1.           #Execute the Demo Application
2.           echo "Demo Application: Executing ..."
3.           export HEAPTRC="log=demo_heap.log"; ./demo_hash-lists.dbg.run 2>./demo_error.log 1>./demo_exec.log ; error_code=$?
4.           echo "Demo Application: Execution finished with [$error_code]"
5.           #Demo Application Execution Report
6.           echo "Demo Execution Log:" ; cat ./demo_exec.log
7.           echo "Demo Execution Error:" ; cat ./demo_error.log
8.           echo "Demo Execution Heap:" ; cat ./demo_heap.log
9.           error=`cat ./demo_error.log` ; if [ -n "$error" ]; then echo "Demo failed with Error [Code: '$error_code']" && exit 1; fi ;
10.           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 ;
11.  

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 (https://github.com/bodo-hugo-barwich/hash-lists/runs/1403236831?check_suite_focus=true)

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.