Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ovs-vswitchd: possible memory leak in 2.12.0 (issue is happening since 2.10.1 at least) #168

Closed
casasfernando opened this issue Mar 2, 2019 · 26 comments

Comments

@casasfernando
Copy link

casasfernando commented Mar 2, 2019

I'm running OVS on a Qemu/KVM virtualization host for a while now. The virtualization host is running around 12 VMs without a huge network activity. The OVS configuration is very simple, nothing fancy. Four VLANs, two bond ports with two slaves each, three internal ports and then one port for each VM (I can provide the output of ovs-vsctl show if needed).

Recently I noticed that when the ovs-vswitchd process starts it's consuming around 10MB of RAM but after two weeks (the server is running 24x7) ovs-vswitchd can be consuming around 2.5GB of RAM and after let's say a month or so it will be around 5GB or even a bit more.

What I'm doing now to keep ovs-vswitchd memory usage under control is to restart the service every couple of weeks but this is far from ideal.

Please find below some additional information about my setup and feel free to ask for any other details I may have missed.

OVS command line: /usr/sbin/ovs-vswitchd --pidfile=/var/run/openvswitch/ovs-vswitchd.pid --detach --monitor --mlockall unix:/var/run/openvswitch/db.sock
OVS version: 2.10.1
Distro: Alpine Linux 3.9.0
Linux kernel version: 4.19.18
Qemu version: 3.1
Libvirt version: 4.10.0

OVS memory usage from log file:

2018-09-07T22:02:54+02:00 vmsvr01 ovs-vswitchd: ovs|00030|memory|INFO|10316 kB peak resident set size after 10.0 seconds
2018-09-07T22:02:54+02:00 vmsvr01 ovs-vswitchd: ovs|00031|memory|INFO|handlers:5 ports:2 revalidators:3 rules:5 udpif keys:23
2018-09-07T22:12:05+02:00 vmsvr01 ovs-vswitchd: ovs|00030|memory|INFO|10316 kB peak resident set size after 10.0 seconds
2018-09-07T22:12:05+02:00 vmsvr01 ovs-vswitchd: ovs|00031|memory|INFO|handlers:5 ports:2 revalidators:3 rules:5 udpif keys:21
2018-09-08T10:48:18+02:00 vmsvr01 ovs-vswitchd: ovs|00702|memory|INFO|peak resident set size grew 51% in last 3472.0 seconds, from 10300 kB to 15572 kB
2018-09-08T10:48:18+02:00 vmsvr01 ovs-vswitchd: ovs|00703|memory|INFO|handlers:5 ports:13 revalidators:3 rules:5 udpif keys:18
2018-09-08T12:21:11+02:00 vmsvr01 ovs-vswitchd: ovs|00704|memory|INFO|peak resident set size grew 51% in last 5573.2 seconds, from 15572 kB to 23492 kB
2018-09-08T12:21:11+02:00 vmsvr01 ovs-vswitchd: ovs|00705|memory|INFO|handlers:5 ports:13 revalidators:3 rules:5 udpif keys:32
2018-09-08T14:46:16+02:00 vmsvr01 ovs-vswitchd: ovs|00706|memory|INFO|peak resident set size grew 51% in last 8705.3 seconds, from 23492 kB to 35372 kB
2018-09-08T14:46:16+02:00 vmsvr01 ovs-vswitchd: ovs|00707|memory|INFO|handlers:5 ports:13 revalidators:3 rules:5 udpif keys:16
2018-09-08T17:46:03+02:00 vmsvr01 ovs-vswitchd: ovs|00708|memory|INFO|peak resident set size grew 50% in last 10786.3 seconds, from 35372 kB to 53060 kB
2018-09-08T17:46:03+02:00 vmsvr01 ovs-vswitchd: ovs|00709|memory|INFO|handlers:5 ports:13 revalidators:3 rules:5 udpif keys:18
2018-09-08T23:08:45+02:00 vmsvr01 ovs-vswitchd: ovs|00720|memory|INFO|peak resident set size grew 50% in last 19362.0 seconds, from 53060 kB to 79724 kB
2018-09-08T23:08:45+02:00 vmsvr01 ovs-vswitchd: ovs|00721|memory|INFO|handlers:5 ports:14 revalidators:3 rules:5 udpif keys:27
2018-09-09T06:41:39+02:00 vmsvr01 ovs-vswitchd: ovs|00722|memory|INFO|peak resident set size grew 50% in last 27174.2 seconds, from 79724 kB to 119588 kB
2018-09-09T06:41:39+02:00 vmsvr01 ovs-vswitchd: ovs|00723|memory|INFO|handlers:5 ports:14 revalidators:3 rules:5 udpif keys:26
2018-09-09T18:02:35+02:00 vmsvr01 ovs-vswitchd: ovs|00724|memory|INFO|peak resident set size grew 50% in last 40856.1 seconds, from 119588 kB to 179516 kB
2018-09-09T18:02:35+02:00 vmsvr01 ovs-vswitchd: ovs|00725|memory|INFO|handlers:5 ports:14 revalidators:3 rules:5 udpif keys:37
2018-09-10T10:58:41+02:00 vmsvr01 ovs-vswitchd: ovs|00727|memory|INFO|peak resident set size grew 50% in last 60965.9 seconds, from 179516 kB to 269276 kB
2018-09-10T10:58:41+02:00 vmsvr01 ovs-vswitchd: ovs|00728|memory|INFO|handlers:5 ports:15 revalidators:3 rules:5 udpif keys:39
2018-09-11T14:54:02+02:00 vmsvr01 ovs-vswitchd: ovs|00734|memory|INFO|peak resident set size grew 50% in last 100521.3 seconds, from 269276 kB to 403916 kB
2018-09-11T14:54:02+02:00 vmsvr01 ovs-vswitchd: ovs|00735|memory|INFO|handlers:5 ports:14 revalidators:3 rules:5 udpif keys:16
2018-09-13T08:06:22+02:00 vmsvr01 ovs-vswitchd: ovs|00740|memory|INFO|peak resident set size grew 50% in last 148339.4 seconds, from 403916 kB to 605876 kB
2018-09-13T08:06:22+02:00 vmsvr01 ovs-vswitchd: ovs|00741|memory|INFO|handlers:5 ports:15 revalidators:3 rules:5 udpif keys:15
2018-09-15T21:54:39+02:00 vmsvr01 ovs-vswitchd: ovs|00750|memory|INFO|peak resident set size grew 50% in last 222497.4 seconds, from 605876 kB to 908948 kB
2018-09-15T21:54:39+02:00 vmsvr01 ovs-vswitchd: ovs|00751|memory|INFO|handlers:5 ports:14 revalidators:3 rules:5 udpif keys:20
2018-09-19T18:15:25+02:00 vmsvr01 ovs-vswitchd: ovs|00763|memory|INFO|peak resident set size grew 50% in last 332445.8 seconds, from 908948 kB to 1363556 kB
2018-09-19T18:15:25+02:00 vmsvr01 ovs-vswitchd: ovs|00764|memory|INFO|handlers:5 ports:13 revalidators:3 rules:5 udpif keys:46
2018-09-25T11:54:40+02:00 vmsvr01 ovs-vswitchd: ovs|00855|memory|INFO|peak resident set size grew 50% in last 495554.7 seconds, from 1363556 kB to 2045468 kB
2018-09-25T11:54:40+02:00 vmsvr01 ovs-vswitchd: ovs|00856|memory|INFO|handlers:5 ports:16 revalidators:3 rules:5 udpif keys:53
2018-10-04T08:31:40+02:00 vmsvr01 ovs-vswitchd: ovs|00888|memory|INFO|peak resident set size grew 50% in last 765420.9 seconds, from 2045468 kB to 3068204 kB
2018-10-04T08:31:40+02:00 vmsvr01 ovs-vswitchd: ovs|00889|memory|INFO|handlers:5 ports:14 revalidators:3 rules:5 udpif keys:42
2018-10-16T14:45:35+02:00 vmsvr01 ovs-vswitchd: ovs|00911|memory|INFO|peak resident set size grew 50% in last 1059234.5 seconds, from 3068204 kB to 4602308 kB
2018-10-16T14:45:35+02:00 vmsvr01 ovs-vswitchd: ovs|00912|memory|INFO|handlers:5 ports:14 revalidators:3 rules:5 udpif keys:27
2018-11-04T06:27:02+01:00 vmsvr01 ovs-vswitchd: ovs|01015|memory|INFO|peak resident set size grew 50% in last 1615287.6 seconds, from 4602308 kB to 6903596 kB
2018-11-04T06:27:02+01:00 vmsvr01 ovs-vswitchd: ovs|01016|memory|INFO|handlers:5 ports:13 revalidators:3 rules:5 udpif keys:1
2018-12-01T19:28:14+01:00 vmsvr01 ovs-vswitchd: ovs|01092|memory|INFO|peak resident set size grew 50% in last 2379671.3 seconds, from 6903596 kB to 10355396 kB
2018-12-01T19:28:14+01:00 vmsvr01 ovs-vswitchd: ovs|01093|memory|INFO|handlers:5 ports:13 revalidators:3 rules:5 udpif keys:18
2019-01-12T13:12:25+01:00 vmsvr01 ovs-vswitchd: ovs|01234|memory|INFO|peak resident set size grew 50% in last 3606251.1 seconds, from 10355396 kB to 15533228 kB
2019-01-12T13:12:25+01:00 vmsvr01 ovs-vswitchd: ovs|01235|memory|INFO|handlers:5 ports:13 revalidators:3 rules:5 udpif keys:46

Also I'm attaching two screenshots from Munin monitoring ovs-vswitchd rss size and meminfo for around five days and how memory usage growth is almost linear to time.

rss_ovs-vswitchd

meminfo_ovs-vswitchd

I can provide a memory dump of the process while consuming 500MB of RAM (collected using gcore) if that would help.

Please let me know if you need any more details.

@pedh
Copy link

pedh commented Mar 8, 2019

Possibly related to this issue.
The ovs-vswitchd process abnormally dies after some simple steps.

Here is the steps:

  1. Add a bridge br0
  2. Set the controller of br0 to tcp:127.0.0.1:6653
  3. Create an simple openflow controller listening to tcp :::6653, with basic ofp hello and echo reply handling,
  4. Use ovs-ofctl to mod several flows to br0
  5. Stop the openflow controller.
  6. Repeat step 3 to 5, after several times the ovs-vswitchd process is terminated by sigabrt.

My environment
CentOS 7.6
openvwitch 2.10.1 from the centos openstack rocky repo

The suspicious ovs-vswitchd log
INFO|168264 kB peak resident set size after 10.1 seconds

@camrossi
Copy link

camrossi commented Jul 9, 2019

Hello,

I am seeing the same in 2.10.1 and 2.10.1-r2.
I just run a batch job that keeps creating destroying containers and the OVS mem utilisation keeps climbing. It went from 46MB to 439MB in roughly 16h.

@damijans
Copy link

damijans commented Jul 26, 2019

I believe I have addressed this issue.
Pls see https://mail.openvswitch.org/pipermail/ovs-dev/2019-July/361062.html

ovsrobot pushed a commit to ovsrobot/ovs that referenced this issue Jul 26, 2019
While checking valgrind reports after running "make check-valgrind" I have noticed
reports for several tests similar to the following:

....
==5345== Memcheck, a memory error detector
==5345== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5345== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5345== Command: ovsdb-client --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem transact ssl:127.0.0.1:40111 \ \ \ ["ordinals",
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["number",\ "==",\ 1]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 2,\ "name":\ "old\ two"}},
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["name",\ "==",\ "two"]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 1,\ "name":\ "old\ one"}}]
==5345== Parent PID: 5344
==5345==
==5345==
==5345== HEAP SUMMARY:
==5345==     in use at exit: 116,551 bytes in 3,341 blocks
==5345==   total heap usage: 5,134 allocs, 1,793 frees, 412,290 bytes allocated
==5345==
==5345== 6,221 (184 direct, 6,037 indirect) bytes in 1 blocks are definitely lost in loss record 498 of 500
==5345==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5345==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x4E56B27: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E5BA11: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E65145: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4522DF: ssl_connect (stream-ssl.c:530)
==5345==    by 0x443D38: scs_connecting (stream.c:315)
==5345==    by 0x443D38: stream_connect (stream.c:338)
==5345==    by 0x443FA1: stream_open_block (stream.c:266)
==5345==    by 0x40AB79: open_jsonrpc (ovsdb-client.c:507)
==5345==    by 0x40AB79: open_rpc (ovsdb-client.c:143)
==5345==    by 0x40B06B: do_transact__ (ovsdb-client.c:871)
==5345==    by 0x40B245: do_transact (ovsdb-client.c:893)
==5345==    by 0x405F76: main (ovsdb-client.c:282)
==5345==
==5345== LEAK SUMMARY:
==5345==    definitely lost: 184 bytes in 1 blocks
==5345==    indirectly lost: 6,037 bytes in 117 blocks
==5345==      possibly lost: 0 bytes in 0 blocks
==5345==    still reachable: 110,330 bytes in 3,223 blocks
==5345==         suppressed: 0 bytes in 0 blocks
==5345== Reachable blocks (those to which a pointer was found) are not shown.
==5345== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5345==
==5345== For counts of detected and suppressed errors, rerun with: -v
==5345== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0)
....

This report was extracted from "index uniqueness checking" test and complains about
leaking memory in ovsdb-client application. The problem is not huge, since ovsdb-client
is CLI tool which is constantly reinvoked/restarted, thus leaked memory is not accumulated.

More problematic issue is that for the same test valgrind reports the similar problem also for
ovsdb-server:

....
==5290== Memcheck, a memory error detector
==5290== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5290== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5290== Command: ovsdb-server --log-file --detach --no-chdir --pidfile --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey2.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert2.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem --remote=pssl:0:127.0.0.1 db
==5290== Parent PID: 5289
==5290==
==5292== Warning: noted but unhandled ioctl 0x2403 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292== Warning: noted but unhandled ioctl 0x2400 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5290==
==5290== HEAP SUMMARY:
==5290==     in use at exit: 2,066 bytes in 48 blocks
==5290==   total heap usage: 87 allocs, 39 frees, 14,152 bytes allocated
==5290==
==5290== LEAK SUMMARY:
==5290==    definitely lost: 0 bytes in 0 blocks
==5290==    indirectly lost: 0 bytes in 0 blocks
==5290==      possibly lost: 0 bytes in 0 blocks
==5290==    still reachable: 2,066 bytes in 48 blocks
==5290==         suppressed: 0 bytes in 0 blocks
==5290== Reachable blocks (those to which a pointer was found) are not shown.
==5290== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5290==
==5290== For counts of detected and suppressed errors, rerun with: -v
==5290== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 1 from 1)
==5292== Warning: noted but unhandled ioctl 0x2401 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292==
==5292== HEAP SUMMARY:
==5292==     in use at exit: 164,018 bytes in 4,252 blocks
==5292==   total heap usage: 17,910 allocs, 13,658 frees, 1,907,468 bytes allocated
==5292==
==5292== 49,720 (1,472 direct, 48,248 indirect) bytes in 8 blocks are definitely lost in loss record 580 of 580
==5292==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5292==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x4E53E00: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x4E55727: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x452C4B: ssl_connect (stream-ssl.c:530)
==5292==    by 0x445B18: scs_connecting (stream.c:315)
==5292==    by 0x445B18: stream_connect (stream.c:338)
==5292==    by 0x445B91: stream_recv (stream.c:369)
==5292==    by 0x432A9C: jsonrpc_recv.part.7 (jsonrpc.c:310)
==5292==    by 0x433977: jsonrpc_recv (jsonrpc.c:1139)
==5292==    by 0x433977: jsonrpc_session_recv (jsonrpc.c:1112)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run (jsonrpc-server.c:553)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run_all (jsonrpc-server.c:586)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_server_run (jsonrpc-server.c:401)
==5292==    by 0x40682E: main_loop (ovsdb-server.c:209)
==5292==    by 0x40682E: main (ovsdb-server.c:460)
==5292==
==5292== LEAK SUMMARY:
==5292==    definitely lost: 1,472 bytes in 8 blocks
==5292==    indirectly lost: 48,248 bytes in 936 blocks
==5292==      possibly lost: 0 bytes in 0 blocks
==5292==    still reachable: 114,298 bytes in 3,308 blocks
==5292==         suppressed: 0 bytes in 0 blocks
==5292== Reachable blocks (those to which a pointer was found) are not shown.
==5292== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5292==
==5292== For counts of detected and suppressed errors, rerun with: -v
==5292== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 1 from 1)
....

In this case ovsdb-server is running as daemon process (--detach option) and leaking memory is
accumulated whenever ovsdb-client is reconnected. Within observed test ovsdb-client CLI tool
connects 8 times to ovsdb-server. Leaked memory in ovsdb-client (for each invocation) is approx.
6K bytes, while leaked memory in ovsdb-server is aprox. 48Kbytes what is actually 8*6K. Thus per
each connection both ovsdb-client and ovsdb-server leak approx. 6K bytes.

I have done a small manual test to check if ovsdb-server is indeed accumulating leaked memory
by dumping ovsdb-server in a loop:

console1:
ovsdb-server \
--log-file \
--detach --no-chdir --pidfile \
--private-key=testpki-privkey2.pem \
--certificate=testpki-cert2.pem \
--ca-cert=testpki-cacert.pem \
--remote=pssl:0:127.0.0.1 \
db

while (true); do \
ovsdb-client \
--private-key=testpki-privkey.pem \
--certificate=testpki-cert.pem \
--ca-cert=testpki-cacert.pem \
dump ssl:127.0.0.1:42067; \
done

console2:
watch -n 0.5 'cat /proc/$(pidof ovsdb-server)/status | grep VmSize'

In console2 it was evidently seen ovsdb-server is constantly leaking memory. After a while
(i.e. after a certain number of reconnections) the OOM killer jumps out and kills ovsdb-server.

Very similar situation was already noticed and described in
openvswitch/ovs-issues#168. There, the problem pops up while connecting
controller to ovs-vswitchd daemon.

Valgrind reports point to a problem in openssl library, however after studying openssl code for
a while I have found out the problem is actually in ovs. When connection through SSL channel is
taken place openssl library allocates memory for keeping track of certificate. Reference to this
memory works very similar as std::shared_ptr pointer in recent C++ dialects. i.e. when allocated
memory is referenced its reference counter is incremented and decremented after the memory is
derefered. When reference counter becomes zero allocated memory is automatically deallocated.

In openssl library environment certificate is retrieved by calling SSL_get_peer_certificate()
where its reference counter is incremented. After retrieved certificate is not used any more its
reference counter must be decremented by calling X509_free(). If not, allocated memory is never
freed despite the ssl connection is properly closed.

The problem was caused in stream-ssl.c in function ssl_connect(), which retrieves common peer name
by calling SSL_get_peer_certificate() function and without calling X509_free() function afterwards.

Signed-off-by: Damijan Skvarc <damjan.skvarc@gmail.com>
Signed-off-by: 0-day Robot <robot@bytheb.org>
ovsrobot pushed a commit to ovsrobot/ovs that referenced this issue Sep 20, 2019
While checking valgrind reports after running "make check-valgrind" I have noticed
reports for several tests similar to the following:

....
==5345== Memcheck, a memory error detector
==5345== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5345== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5345== Command: ovsdb-client --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem transact ssl:127.0.0.1:40111 \ \ \ ["ordinals",
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["number",\ "==",\ 1]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 2,\ "name":\ "old\ two"}},
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["name",\ "==",\ "two"]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 1,\ "name":\ "old\ one"}}]
==5345== Parent PID: 5344
==5345==
==5345==
==5345== HEAP SUMMARY:
==5345==     in use at exit: 116,551 bytes in 3,341 blocks
==5345==   total heap usage: 5,134 allocs, 1,793 frees, 412,290 bytes allocated
==5345==
==5345== 6,221 (184 direct, 6,037 indirect) bytes in 1 blocks are definitely lost in loss record 498 of 500
==5345==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5345==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x4E56B27: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E5BA11: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E65145: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4522DF: ssl_connect (stream-ssl.c:530)
==5345==    by 0x443D38: scs_connecting (stream.c:315)
==5345==    by 0x443D38: stream_connect (stream.c:338)
==5345==    by 0x443FA1: stream_open_block (stream.c:266)
==5345==    by 0x40AB79: open_jsonrpc (ovsdb-client.c:507)
==5345==    by 0x40AB79: open_rpc (ovsdb-client.c:143)
==5345==    by 0x40B06B: do_transact__ (ovsdb-client.c:871)
==5345==    by 0x40B245: do_transact (ovsdb-client.c:893)
==5345==    by 0x405F76: main (ovsdb-client.c:282)
==5345==
==5345== LEAK SUMMARY:
==5345==    definitely lost: 184 bytes in 1 blocks
==5345==    indirectly lost: 6,037 bytes in 117 blocks
==5345==      possibly lost: 0 bytes in 0 blocks
==5345==    still reachable: 110,330 bytes in 3,223 blocks
==5345==         suppressed: 0 bytes in 0 blocks
==5345== Reachable blocks (those to which a pointer was found) are not shown.
==5345== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5345==
==5345== For counts of detected and suppressed errors, rerun with: -v
==5345== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0)
....

This report was extracted from "index uniqueness checking" test and complains about
leaking memory in ovsdb-client application. The problem is not huge, since ovsdb-client
is CLI tool which is constantly reinvoked/restarted, thus leaked memory is not accumulated.

More problematic issue is that for the same test valgrind reports the similar problem also for
ovsdb-server:

....
==5290== Memcheck, a memory error detector
==5290== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5290== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5290== Command: ovsdb-server --log-file --detach --no-chdir --pidfile --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey2.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert2.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem --remote=pssl:0:127.0.0.1 db
==5290== Parent PID: 5289
==5290==
==5292== Warning: noted but unhandled ioctl 0x2403 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292== Warning: noted but unhandled ioctl 0x2400 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5290==
==5290== HEAP SUMMARY:
==5290==     in use at exit: 2,066 bytes in 48 blocks
==5290==   total heap usage: 87 allocs, 39 frees, 14,152 bytes allocated
==5290==
==5290== LEAK SUMMARY:
==5290==    definitely lost: 0 bytes in 0 blocks
==5290==    indirectly lost: 0 bytes in 0 blocks
==5290==      possibly lost: 0 bytes in 0 blocks
==5290==    still reachable: 2,066 bytes in 48 blocks
==5290==         suppressed: 0 bytes in 0 blocks
==5290== Reachable blocks (those to which a pointer was found) are not shown.
==5290== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5290==
==5290== For counts of detected and suppressed errors, rerun with: -v
==5290== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 1 from 1)
==5292== Warning: noted but unhandled ioctl 0x2401 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292==
==5292== HEAP SUMMARY:
==5292==     in use at exit: 164,018 bytes in 4,252 blocks
==5292==   total heap usage: 17,910 allocs, 13,658 frees, 1,907,468 bytes allocated
==5292==
==5292== 49,720 (1,472 direct, 48,248 indirect) bytes in 8 blocks are definitely lost in loss record 580 of 580
==5292==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5292==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x4E53E00: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x4E55727: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x452C4B: ssl_connect (stream-ssl.c:530)
==5292==    by 0x445B18: scs_connecting (stream.c:315)
==5292==    by 0x445B18: stream_connect (stream.c:338)
==5292==    by 0x445B91: stream_recv (stream.c:369)
==5292==    by 0x432A9C: jsonrpc_recv.part.7 (jsonrpc.c:310)
==5292==    by 0x433977: jsonrpc_recv (jsonrpc.c:1139)
==5292==    by 0x433977: jsonrpc_session_recv (jsonrpc.c:1112)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run (jsonrpc-server.c:553)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run_all (jsonrpc-server.c:586)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_server_run (jsonrpc-server.c:401)
==5292==    by 0x40682E: main_loop (ovsdb-server.c:209)
==5292==    by 0x40682E: main (ovsdb-server.c:460)
==5292==
==5292== LEAK SUMMARY:
==5292==    definitely lost: 1,472 bytes in 8 blocks
==5292==    indirectly lost: 48,248 bytes in 936 blocks
==5292==      possibly lost: 0 bytes in 0 blocks
==5292==    still reachable: 114,298 bytes in 3,308 blocks
==5292==         suppressed: 0 bytes in 0 blocks
==5292== Reachable blocks (those to which a pointer was found) are not shown.
==5292== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5292==
==5292== For counts of detected and suppressed errors, rerun with: -v
==5292== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 1 from 1)
....

In this case ovsdb-server is running as daemon process (--detach option) and leaking memory is
accumulated whenever ovsdb-client is reconnected. Within observed test ovsdb-client CLI tool
connects 8 times to ovsdb-server. Leaked memory in ovsdb-client (for each invocation) is approx.
6K bytes, while leaked memory in ovsdb-server is aprox. 48Kbytes what is actually 8*6K. Thus per
each connection both ovsdb-client and ovsdb-server leak approx. 6K bytes.

I have done a small manual test to check if ovsdb-server is indeed accumulating leaked memory
by dumping ovsdb-server in a loop:

console1:
ovsdb-server \
--log-file \
--detach --no-chdir --pidfile \
--private-key=testpki-privkey2.pem \
--certificate=testpki-cert2.pem \
--ca-cert=testpki-cacert.pem \
--remote=pssl:0:127.0.0.1 \
db

while (true); do \
ovsdb-client \
--private-key=testpki-privkey.pem \
--certificate=testpki-cert.pem \
--ca-cert=testpki-cacert.pem \
dump ssl:127.0.0.1:42067; \
done

console2:
watch -n 0.5 'cat /proc/$(pidof ovsdb-server)/status | grep VmSize'

In console2 it was evidently seen ovsdb-server is constantly leaking memory. After a while
(i.e. after a certain number of reconnections) the OOM killer jumps out and kills ovsdb-server.

Very similar situation was already noticed and described in
openvswitch/ovs-issues#168. There, the problem pops up while connecting
controller to ovs-vswitchd daemon.

Valgrind reports point to a problem in openssl library, however after studying openssl code for
a while I have found out the problem is actually in ovs. When connection through SSL channel is
taken place openssl library allocates memory for keeping track of certificate. Reference to this
memory works very similar as std::shared_ptr pointer in recent C++ dialects. i.e. when allocated
memory is referenced its reference counter is incremented and decremented after the memory is
derefered. When reference counter becomes zero allocated memory is automatically deallocated.

In openssl library environment certificate is retrieved by calling SSL_get_peer_certificate()
where its reference counter is incremented. After retrieved certificate is not used any more its
reference counter must be decremented by calling X509_free(). If not, allocated memory is never
freed despite the ssl connection is properly closed.

The problem was caused in stream-ssl.c in function ssl_connect(), which retrieves common peer name
by calling SSL_get_peer_certificate() function and without calling X509_free() function afterwards.

Signed-off-by: Damijan Skvarc <damjan.skvarc@gmail.com>
Signed-off-by: William Tu <u9012063@gmail.com>
Signed-off-by: 0-day Robot <robot@bytheb.org>
blp pushed a commit to openvswitch/ovs that referenced this issue Sep 23, 2019
While checking valgrind reports after running "make check-valgrind" I have noticed
reports for several tests similar to the following:

....
==5345== Memcheck, a memory error detector
==5345== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5345== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5345== Command: ovsdb-client --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem transact ssl:127.0.0.1:40111 \ \ \ ["ordinals",
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["number",\ "==",\ 1]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 2,\ "name":\ "old\ two"}},
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["name",\ "==",\ "two"]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 1,\ "name":\ "old\ one"}}]
==5345== Parent PID: 5344
==5345==
==5345==
==5345== HEAP SUMMARY:
==5345==     in use at exit: 116,551 bytes in 3,341 blocks
==5345==   total heap usage: 5,134 allocs, 1,793 frees, 412,290 bytes allocated
==5345==
==5345== 6,221 (184 direct, 6,037 indirect) bytes in 1 blocks are definitely lost in loss record 498 of 500
==5345==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5345==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x4E56B27: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E5BA11: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E65145: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4522DF: ssl_connect (stream-ssl.c:530)
==5345==    by 0x443D38: scs_connecting (stream.c:315)
==5345==    by 0x443D38: stream_connect (stream.c:338)
==5345==    by 0x443FA1: stream_open_block (stream.c:266)
==5345==    by 0x40AB79: open_jsonrpc (ovsdb-client.c:507)
==5345==    by 0x40AB79: open_rpc (ovsdb-client.c:143)
==5345==    by 0x40B06B: do_transact__ (ovsdb-client.c:871)
==5345==    by 0x40B245: do_transact (ovsdb-client.c:893)
==5345==    by 0x405F76: main (ovsdb-client.c:282)
==5345==
==5345== LEAK SUMMARY:
==5345==    definitely lost: 184 bytes in 1 blocks
==5345==    indirectly lost: 6,037 bytes in 117 blocks
==5345==      possibly lost: 0 bytes in 0 blocks
==5345==    still reachable: 110,330 bytes in 3,223 blocks
==5345==         suppressed: 0 bytes in 0 blocks
==5345== Reachable blocks (those to which a pointer was found) are not shown.
==5345== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5345==
==5345== For counts of detected and suppressed errors, rerun with: -v
==5345== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0)
....

This report was extracted from "index uniqueness checking" test and complains about
leaking memory in ovsdb-client application. The problem is not huge, since ovsdb-client
is CLI tool which is constantly reinvoked/restarted, thus leaked memory is not accumulated.

More problematic issue is that for the same test valgrind reports the similar problem also for
ovsdb-server:

....
==5290== Memcheck, a memory error detector
==5290== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5290== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5290== Command: ovsdb-server --log-file --detach --no-chdir --pidfile --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey2.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert2.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem --remote=pssl:0:127.0.0.1 db
==5290== Parent PID: 5289
==5290==
==5292== Warning: noted but unhandled ioctl 0x2403 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292== Warning: noted but unhandled ioctl 0x2400 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5290==
==5290== HEAP SUMMARY:
==5290==     in use at exit: 2,066 bytes in 48 blocks
==5290==   total heap usage: 87 allocs, 39 frees, 14,152 bytes allocated
==5290==
==5290== LEAK SUMMARY:
==5290==    definitely lost: 0 bytes in 0 blocks
==5290==    indirectly lost: 0 bytes in 0 blocks
==5290==      possibly lost: 0 bytes in 0 blocks
==5290==    still reachable: 2,066 bytes in 48 blocks
==5290==         suppressed: 0 bytes in 0 blocks
==5290== Reachable blocks (those to which a pointer was found) are not shown.
==5290== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5290==
==5290== For counts of detected and suppressed errors, rerun with: -v
==5290== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 1 from 1)
==5292== Warning: noted but unhandled ioctl 0x2401 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292==
==5292== HEAP SUMMARY:
==5292==     in use at exit: 164,018 bytes in 4,252 blocks
==5292==   total heap usage: 17,910 allocs, 13,658 frees, 1,907,468 bytes allocated
==5292==
==5292== 49,720 (1,472 direct, 48,248 indirect) bytes in 8 blocks are definitely lost in loss record 580 of 580
==5292==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5292==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x4E53E00: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x4E55727: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x452C4B: ssl_connect (stream-ssl.c:530)
==5292==    by 0x445B18: scs_connecting (stream.c:315)
==5292==    by 0x445B18: stream_connect (stream.c:338)
==5292==    by 0x445B91: stream_recv (stream.c:369)
==5292==    by 0x432A9C: jsonrpc_recv.part.7 (jsonrpc.c:310)
==5292==    by 0x433977: jsonrpc_recv (jsonrpc.c:1139)
==5292==    by 0x433977: jsonrpc_session_recv (jsonrpc.c:1112)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run (jsonrpc-server.c:553)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run_all (jsonrpc-server.c:586)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_server_run (jsonrpc-server.c:401)
==5292==    by 0x40682E: main_loop (ovsdb-server.c:209)
==5292==    by 0x40682E: main (ovsdb-server.c:460)
==5292==
==5292== LEAK SUMMARY:
==5292==    definitely lost: 1,472 bytes in 8 blocks
==5292==    indirectly lost: 48,248 bytes in 936 blocks
==5292==      possibly lost: 0 bytes in 0 blocks
==5292==    still reachable: 114,298 bytes in 3,308 blocks
==5292==         suppressed: 0 bytes in 0 blocks
==5292== Reachable blocks (those to which a pointer was found) are not shown.
==5292== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5292==
==5292== For counts of detected and suppressed errors, rerun with: -v
==5292== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 1 from 1)
....

In this case ovsdb-server is running as daemon process (--detach option) and leaking memory is
accumulated whenever ovsdb-client is reconnected. Within observed test ovsdb-client CLI tool
connects 8 times to ovsdb-server. Leaked memory in ovsdb-client (for each invocation) is approx.
6K bytes, while leaked memory in ovsdb-server is aprox. 48Kbytes what is actually 8*6K. Thus per
each connection both ovsdb-client and ovsdb-server leak approx. 6K bytes.

I have done a small manual test to check if ovsdb-server is indeed accumulating leaked memory
by dumping ovsdb-server in a loop:

console1:
ovsdb-server \
--log-file \
--detach --no-chdir --pidfile \
--private-key=testpki-privkey2.pem \
--certificate=testpki-cert2.pem \
--ca-cert=testpki-cacert.pem \
--remote=pssl:0:127.0.0.1 \
db

while (true); do \
ovsdb-client \
--private-key=testpki-privkey.pem \
--certificate=testpki-cert.pem \
--ca-cert=testpki-cacert.pem \
dump ssl:127.0.0.1:42067; \
done

console2:
watch -n 0.5 'cat /proc/$(pidof ovsdb-server)/status | grep VmSize'

In console2 it was evidently seen ovsdb-server is constantly leaking memory. After a while
(i.e. after a certain number of reconnections) the OOM killer jumps out and kills ovsdb-server.

Very similar situation was already noticed and described in
openvswitch/ovs-issues#168. There, the problem pops up while connecting
controller to ovs-vswitchd daemon.

Valgrind reports point to a problem in openssl library, however after studying openssl code for
a while I have found out the problem is actually in ovs. When connection through SSL channel is
taken place openssl library allocates memory for keeping track of certificate. Reference to this
memory works very similar as std::shared_ptr pointer in recent C++ dialects. i.e. when allocated
memory is referenced its reference counter is incremented and decremented after the memory is
derefered. When reference counter becomes zero allocated memory is automatically deallocated.

In openssl library environment certificate is retrieved by calling SSL_get_peer_certificate()
where its reference counter is incremented. After retrieved certificate is not used any more its
reference counter must be decremented by calling X509_free(). If not, allocated memory is never
freed despite the ssl connection is properly closed.

The problem was caused in stream-ssl.c in function ssl_connect(), which retrieves common peer name
by calling SSL_get_peer_certificate() function and without calling X509_free() function afterwards.

Signed-off-by: Damijan Skvarc <damjan.skvarc@gmail.com>
Signed-off-by: Ben Pfaff <blp@ovn.org>
blp pushed a commit to openvswitch/ovs that referenced this issue Sep 23, 2019
While checking valgrind reports after running "make check-valgrind" I have noticed
reports for several tests similar to the following:

....
==5345== Memcheck, a memory error detector
==5345== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5345== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5345== Command: ovsdb-client --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem transact ssl:127.0.0.1:40111 \ \ \ ["ordinals",
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["number",\ "==",\ 1]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 2,\ "name":\ "old\ two"}},
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["name",\ "==",\ "two"]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 1,\ "name":\ "old\ one"}}]
==5345== Parent PID: 5344
==5345==
==5345==
==5345== HEAP SUMMARY:
==5345==     in use at exit: 116,551 bytes in 3,341 blocks
==5345==   total heap usage: 5,134 allocs, 1,793 frees, 412,290 bytes allocated
==5345==
==5345== 6,221 (184 direct, 6,037 indirect) bytes in 1 blocks are definitely lost in loss record 498 of 500
==5345==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5345==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x4E56B27: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E5BA11: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E65145: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4522DF: ssl_connect (stream-ssl.c:530)
==5345==    by 0x443D38: scs_connecting (stream.c:315)
==5345==    by 0x443D38: stream_connect (stream.c:338)
==5345==    by 0x443FA1: stream_open_block (stream.c:266)
==5345==    by 0x40AB79: open_jsonrpc (ovsdb-client.c:507)
==5345==    by 0x40AB79: open_rpc (ovsdb-client.c:143)
==5345==    by 0x40B06B: do_transact__ (ovsdb-client.c:871)
==5345==    by 0x40B245: do_transact (ovsdb-client.c:893)
==5345==    by 0x405F76: main (ovsdb-client.c:282)
==5345==
==5345== LEAK SUMMARY:
==5345==    definitely lost: 184 bytes in 1 blocks
==5345==    indirectly lost: 6,037 bytes in 117 blocks
==5345==      possibly lost: 0 bytes in 0 blocks
==5345==    still reachable: 110,330 bytes in 3,223 blocks
==5345==         suppressed: 0 bytes in 0 blocks
==5345== Reachable blocks (those to which a pointer was found) are not shown.
==5345== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5345==
==5345== For counts of detected and suppressed errors, rerun with: -v
==5345== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0)
....

This report was extracted from "index uniqueness checking" test and complains about
leaking memory in ovsdb-client application. The problem is not huge, since ovsdb-client
is CLI tool which is constantly reinvoked/restarted, thus leaked memory is not accumulated.

More problematic issue is that for the same test valgrind reports the similar problem also for
ovsdb-server:

....
==5290== Memcheck, a memory error detector
==5290== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5290== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5290== Command: ovsdb-server --log-file --detach --no-chdir --pidfile --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey2.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert2.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem --remote=pssl:0:127.0.0.1 db
==5290== Parent PID: 5289
==5290==
==5292== Warning: noted but unhandled ioctl 0x2403 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292== Warning: noted but unhandled ioctl 0x2400 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5290==
==5290== HEAP SUMMARY:
==5290==     in use at exit: 2,066 bytes in 48 blocks
==5290==   total heap usage: 87 allocs, 39 frees, 14,152 bytes allocated
==5290==
==5290== LEAK SUMMARY:
==5290==    definitely lost: 0 bytes in 0 blocks
==5290==    indirectly lost: 0 bytes in 0 blocks
==5290==      possibly lost: 0 bytes in 0 blocks
==5290==    still reachable: 2,066 bytes in 48 blocks
==5290==         suppressed: 0 bytes in 0 blocks
==5290== Reachable blocks (those to which a pointer was found) are not shown.
==5290== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5290==
==5290== For counts of detected and suppressed errors, rerun with: -v
==5290== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 1 from 1)
==5292== Warning: noted but unhandled ioctl 0x2401 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292==
==5292== HEAP SUMMARY:
==5292==     in use at exit: 164,018 bytes in 4,252 blocks
==5292==   total heap usage: 17,910 allocs, 13,658 frees, 1,907,468 bytes allocated
==5292==
==5292== 49,720 (1,472 direct, 48,248 indirect) bytes in 8 blocks are definitely lost in loss record 580 of 580
==5292==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5292==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x4E53E00: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x4E55727: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x452C4B: ssl_connect (stream-ssl.c:530)
==5292==    by 0x445B18: scs_connecting (stream.c:315)
==5292==    by 0x445B18: stream_connect (stream.c:338)
==5292==    by 0x445B91: stream_recv (stream.c:369)
==5292==    by 0x432A9C: jsonrpc_recv.part.7 (jsonrpc.c:310)
==5292==    by 0x433977: jsonrpc_recv (jsonrpc.c:1139)
==5292==    by 0x433977: jsonrpc_session_recv (jsonrpc.c:1112)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run (jsonrpc-server.c:553)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run_all (jsonrpc-server.c:586)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_server_run (jsonrpc-server.c:401)
==5292==    by 0x40682E: main_loop (ovsdb-server.c:209)
==5292==    by 0x40682E: main (ovsdb-server.c:460)
==5292==
==5292== LEAK SUMMARY:
==5292==    definitely lost: 1,472 bytes in 8 blocks
==5292==    indirectly lost: 48,248 bytes in 936 blocks
==5292==      possibly lost: 0 bytes in 0 blocks
==5292==    still reachable: 114,298 bytes in 3,308 blocks
==5292==         suppressed: 0 bytes in 0 blocks
==5292== Reachable blocks (those to which a pointer was found) are not shown.
==5292== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5292==
==5292== For counts of detected and suppressed errors, rerun with: -v
==5292== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 1 from 1)
....

In this case ovsdb-server is running as daemon process (--detach option) and leaking memory is
accumulated whenever ovsdb-client is reconnected. Within observed test ovsdb-client CLI tool
connects 8 times to ovsdb-server. Leaked memory in ovsdb-client (for each invocation) is approx.
6K bytes, while leaked memory in ovsdb-server is aprox. 48Kbytes what is actually 8*6K. Thus per
each connection both ovsdb-client and ovsdb-server leak approx. 6K bytes.

I have done a small manual test to check if ovsdb-server is indeed accumulating leaked memory
by dumping ovsdb-server in a loop:

console1:
ovsdb-server \
--log-file \
--detach --no-chdir --pidfile \
--private-key=testpki-privkey2.pem \
--certificate=testpki-cert2.pem \
--ca-cert=testpki-cacert.pem \
--remote=pssl:0:127.0.0.1 \
db

while (true); do \
ovsdb-client \
--private-key=testpki-privkey.pem \
--certificate=testpki-cert.pem \
--ca-cert=testpki-cacert.pem \
dump ssl:127.0.0.1:42067; \
done

console2:
watch -n 0.5 'cat /proc/$(pidof ovsdb-server)/status | grep VmSize'

In console2 it was evidently seen ovsdb-server is constantly leaking memory. After a while
(i.e. after a certain number of reconnections) the OOM killer jumps out and kills ovsdb-server.

Very similar situation was already noticed and described in
openvswitch/ovs-issues#168. There, the problem pops up while connecting
controller to ovs-vswitchd daemon.

Valgrind reports point to a problem in openssl library, however after studying openssl code for
a while I have found out the problem is actually in ovs. When connection through SSL channel is
taken place openssl library allocates memory for keeping track of certificate. Reference to this
memory works very similar as std::shared_ptr pointer in recent C++ dialects. i.e. when allocated
memory is referenced its reference counter is incremented and decremented after the memory is
derefered. When reference counter becomes zero allocated memory is automatically deallocated.

In openssl library environment certificate is retrieved by calling SSL_get_peer_certificate()
where its reference counter is incremented. After retrieved certificate is not used any more its
reference counter must be decremented by calling X509_free(). If not, allocated memory is never
freed despite the ssl connection is properly closed.

The problem was caused in stream-ssl.c in function ssl_connect(), which retrieves common peer name
by calling SSL_get_peer_certificate() function and without calling X509_free() function afterwards.

Signed-off-by: Damijan Skvarc <damjan.skvarc@gmail.com>
Signed-off-by: Ben Pfaff <blp@ovn.org>
blp pushed a commit to openvswitch/ovs that referenced this issue Sep 23, 2019
While checking valgrind reports after running "make check-valgrind" I have noticed
reports for several tests similar to the following:

....
==5345== Memcheck, a memory error detector
==5345== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5345== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5345== Command: ovsdb-client --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem transact ssl:127.0.0.1:40111 \ \ \ ["ordinals",
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["number",\ "==",\ 1]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 2,\ "name":\ "old\ two"}},
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["name",\ "==",\ "two"]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 1,\ "name":\ "old\ one"}}]
==5345== Parent PID: 5344
==5345==
==5345==
==5345== HEAP SUMMARY:
==5345==     in use at exit: 116,551 bytes in 3,341 blocks
==5345==   total heap usage: 5,134 allocs, 1,793 frees, 412,290 bytes allocated
==5345==
==5345== 6,221 (184 direct, 6,037 indirect) bytes in 1 blocks are definitely lost in loss record 498 of 500
==5345==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5345==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x4E56B27: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E5BA11: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E65145: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4522DF: ssl_connect (stream-ssl.c:530)
==5345==    by 0x443D38: scs_connecting (stream.c:315)
==5345==    by 0x443D38: stream_connect (stream.c:338)
==5345==    by 0x443FA1: stream_open_block (stream.c:266)
==5345==    by 0x40AB79: open_jsonrpc (ovsdb-client.c:507)
==5345==    by 0x40AB79: open_rpc (ovsdb-client.c:143)
==5345==    by 0x40B06B: do_transact__ (ovsdb-client.c:871)
==5345==    by 0x40B245: do_transact (ovsdb-client.c:893)
==5345==    by 0x405F76: main (ovsdb-client.c:282)
==5345==
==5345== LEAK SUMMARY:
==5345==    definitely lost: 184 bytes in 1 blocks
==5345==    indirectly lost: 6,037 bytes in 117 blocks
==5345==      possibly lost: 0 bytes in 0 blocks
==5345==    still reachable: 110,330 bytes in 3,223 blocks
==5345==         suppressed: 0 bytes in 0 blocks
==5345== Reachable blocks (those to which a pointer was found) are not shown.
==5345== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5345==
==5345== For counts of detected and suppressed errors, rerun with: -v
==5345== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0)
....

This report was extracted from "index uniqueness checking" test and complains about
leaking memory in ovsdb-client application. The problem is not huge, since ovsdb-client
is CLI tool which is constantly reinvoked/restarted, thus leaked memory is not accumulated.

More problematic issue is that for the same test valgrind reports the similar problem also for
ovsdb-server:

....
==5290== Memcheck, a memory error detector
==5290== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5290== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5290== Command: ovsdb-server --log-file --detach --no-chdir --pidfile --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey2.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert2.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem --remote=pssl:0:127.0.0.1 db
==5290== Parent PID: 5289
==5290==
==5292== Warning: noted but unhandled ioctl 0x2403 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292== Warning: noted but unhandled ioctl 0x2400 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5290==
==5290== HEAP SUMMARY:
==5290==     in use at exit: 2,066 bytes in 48 blocks
==5290==   total heap usage: 87 allocs, 39 frees, 14,152 bytes allocated
==5290==
==5290== LEAK SUMMARY:
==5290==    definitely lost: 0 bytes in 0 blocks
==5290==    indirectly lost: 0 bytes in 0 blocks
==5290==      possibly lost: 0 bytes in 0 blocks
==5290==    still reachable: 2,066 bytes in 48 blocks
==5290==         suppressed: 0 bytes in 0 blocks
==5290== Reachable blocks (those to which a pointer was found) are not shown.
==5290== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5290==
==5290== For counts of detected and suppressed errors, rerun with: -v
==5290== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 1 from 1)
==5292== Warning: noted but unhandled ioctl 0x2401 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292==
==5292== HEAP SUMMARY:
==5292==     in use at exit: 164,018 bytes in 4,252 blocks
==5292==   total heap usage: 17,910 allocs, 13,658 frees, 1,907,468 bytes allocated
==5292==
==5292== 49,720 (1,472 direct, 48,248 indirect) bytes in 8 blocks are definitely lost in loss record 580 of 580
==5292==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5292==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x4E53E00: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x4E55727: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x452C4B: ssl_connect (stream-ssl.c:530)
==5292==    by 0x445B18: scs_connecting (stream.c:315)
==5292==    by 0x445B18: stream_connect (stream.c:338)
==5292==    by 0x445B91: stream_recv (stream.c:369)
==5292==    by 0x432A9C: jsonrpc_recv.part.7 (jsonrpc.c:310)
==5292==    by 0x433977: jsonrpc_recv (jsonrpc.c:1139)
==5292==    by 0x433977: jsonrpc_session_recv (jsonrpc.c:1112)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run (jsonrpc-server.c:553)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run_all (jsonrpc-server.c:586)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_server_run (jsonrpc-server.c:401)
==5292==    by 0x40682E: main_loop (ovsdb-server.c:209)
==5292==    by 0x40682E: main (ovsdb-server.c:460)
==5292==
==5292== LEAK SUMMARY:
==5292==    definitely lost: 1,472 bytes in 8 blocks
==5292==    indirectly lost: 48,248 bytes in 936 blocks
==5292==      possibly lost: 0 bytes in 0 blocks
==5292==    still reachable: 114,298 bytes in 3,308 blocks
==5292==         suppressed: 0 bytes in 0 blocks
==5292== Reachable blocks (those to which a pointer was found) are not shown.
==5292== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5292==
==5292== For counts of detected and suppressed errors, rerun with: -v
==5292== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 1 from 1)
....

In this case ovsdb-server is running as daemon process (--detach option) and leaking memory is
accumulated whenever ovsdb-client is reconnected. Within observed test ovsdb-client CLI tool
connects 8 times to ovsdb-server. Leaked memory in ovsdb-client (for each invocation) is approx.
6K bytes, while leaked memory in ovsdb-server is aprox. 48Kbytes what is actually 8*6K. Thus per
each connection both ovsdb-client and ovsdb-server leak approx. 6K bytes.

I have done a small manual test to check if ovsdb-server is indeed accumulating leaked memory
by dumping ovsdb-server in a loop:

console1:
ovsdb-server \
--log-file \
--detach --no-chdir --pidfile \
--private-key=testpki-privkey2.pem \
--certificate=testpki-cert2.pem \
--ca-cert=testpki-cacert.pem \
--remote=pssl:0:127.0.0.1 \
db

while (true); do \
ovsdb-client \
--private-key=testpki-privkey.pem \
--certificate=testpki-cert.pem \
--ca-cert=testpki-cacert.pem \
dump ssl:127.0.0.1:42067; \
done

console2:
watch -n 0.5 'cat /proc/$(pidof ovsdb-server)/status | grep VmSize'

In console2 it was evidently seen ovsdb-server is constantly leaking memory. After a while
(i.e. after a certain number of reconnections) the OOM killer jumps out and kills ovsdb-server.

Very similar situation was already noticed and described in
openvswitch/ovs-issues#168. There, the problem pops up while connecting
controller to ovs-vswitchd daemon.

Valgrind reports point to a problem in openssl library, however after studying openssl code for
a while I have found out the problem is actually in ovs. When connection through SSL channel is
taken place openssl library allocates memory for keeping track of certificate. Reference to this
memory works very similar as std::shared_ptr pointer in recent C++ dialects. i.e. when allocated
memory is referenced its reference counter is incremented and decremented after the memory is
derefered. When reference counter becomes zero allocated memory is automatically deallocated.

In openssl library environment certificate is retrieved by calling SSL_get_peer_certificate()
where its reference counter is incremented. After retrieved certificate is not used any more its
reference counter must be decremented by calling X509_free(). If not, allocated memory is never
freed despite the ssl connection is properly closed.

The problem was caused in stream-ssl.c in function ssl_connect(), which retrieves common peer name
by calling SSL_get_peer_certificate() function and without calling X509_free() function afterwards.

Signed-off-by: Damijan Skvarc <damjan.skvarc@gmail.com>
Signed-off-by: Ben Pfaff <blp@ovn.org>
blp pushed a commit to openvswitch/ovs that referenced this issue Sep 23, 2019
While checking valgrind reports after running "make check-valgrind" I have noticed
reports for several tests similar to the following:

....
==5345== Memcheck, a memory error detector
==5345== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5345== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5345== Command: ovsdb-client --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem transact ssl:127.0.0.1:40111 \ \ \ ["ordinals",
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["number",\ "==",\ 1]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 2,\ "name":\ "old\ two"}},
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["name",\ "==",\ "two"]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 1,\ "name":\ "old\ one"}}]
==5345== Parent PID: 5344
==5345==
==5345==
==5345== HEAP SUMMARY:
==5345==     in use at exit: 116,551 bytes in 3,341 blocks
==5345==   total heap usage: 5,134 allocs, 1,793 frees, 412,290 bytes allocated
==5345==
==5345== 6,221 (184 direct, 6,037 indirect) bytes in 1 blocks are definitely lost in loss record 498 of 500
==5345==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5345==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x4E56B27: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E5BA11: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E65145: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4522DF: ssl_connect (stream-ssl.c:530)
==5345==    by 0x443D38: scs_connecting (stream.c:315)
==5345==    by 0x443D38: stream_connect (stream.c:338)
==5345==    by 0x443FA1: stream_open_block (stream.c:266)
==5345==    by 0x40AB79: open_jsonrpc (ovsdb-client.c:507)
==5345==    by 0x40AB79: open_rpc (ovsdb-client.c:143)
==5345==    by 0x40B06B: do_transact__ (ovsdb-client.c:871)
==5345==    by 0x40B245: do_transact (ovsdb-client.c:893)
==5345==    by 0x405F76: main (ovsdb-client.c:282)
==5345==
==5345== LEAK SUMMARY:
==5345==    definitely lost: 184 bytes in 1 blocks
==5345==    indirectly lost: 6,037 bytes in 117 blocks
==5345==      possibly lost: 0 bytes in 0 blocks
==5345==    still reachable: 110,330 bytes in 3,223 blocks
==5345==         suppressed: 0 bytes in 0 blocks
==5345== Reachable blocks (those to which a pointer was found) are not shown.
==5345== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5345==
==5345== For counts of detected and suppressed errors, rerun with: -v
==5345== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0)
....

This report was extracted from "index uniqueness checking" test and complains about
leaking memory in ovsdb-client application. The problem is not huge, since ovsdb-client
is CLI tool which is constantly reinvoked/restarted, thus leaked memory is not accumulated.

More problematic issue is that for the same test valgrind reports the similar problem also for
ovsdb-server:

....
==5290== Memcheck, a memory error detector
==5290== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5290== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5290== Command: ovsdb-server --log-file --detach --no-chdir --pidfile --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey2.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert2.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem --remote=pssl:0:127.0.0.1 db
==5290== Parent PID: 5289
==5290==
==5292== Warning: noted but unhandled ioctl 0x2403 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292== Warning: noted but unhandled ioctl 0x2400 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5290==
==5290== HEAP SUMMARY:
==5290==     in use at exit: 2,066 bytes in 48 blocks
==5290==   total heap usage: 87 allocs, 39 frees, 14,152 bytes allocated
==5290==
==5290== LEAK SUMMARY:
==5290==    definitely lost: 0 bytes in 0 blocks
==5290==    indirectly lost: 0 bytes in 0 blocks
==5290==      possibly lost: 0 bytes in 0 blocks
==5290==    still reachable: 2,066 bytes in 48 blocks
==5290==         suppressed: 0 bytes in 0 blocks
==5290== Reachable blocks (those to which a pointer was found) are not shown.
==5290== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5290==
==5290== For counts of detected and suppressed errors, rerun with: -v
==5290== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 1 from 1)
==5292== Warning: noted but unhandled ioctl 0x2401 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292==
==5292== HEAP SUMMARY:
==5292==     in use at exit: 164,018 bytes in 4,252 blocks
==5292==   total heap usage: 17,910 allocs, 13,658 frees, 1,907,468 bytes allocated
==5292==
==5292== 49,720 (1,472 direct, 48,248 indirect) bytes in 8 blocks are definitely lost in loss record 580 of 580
==5292==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5292==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x4E53E00: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x4E55727: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x452C4B: ssl_connect (stream-ssl.c:530)
==5292==    by 0x445B18: scs_connecting (stream.c:315)
==5292==    by 0x445B18: stream_connect (stream.c:338)
==5292==    by 0x445B91: stream_recv (stream.c:369)
==5292==    by 0x432A9C: jsonrpc_recv.part.7 (jsonrpc.c:310)
==5292==    by 0x433977: jsonrpc_recv (jsonrpc.c:1139)
==5292==    by 0x433977: jsonrpc_session_recv (jsonrpc.c:1112)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run (jsonrpc-server.c:553)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run_all (jsonrpc-server.c:586)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_server_run (jsonrpc-server.c:401)
==5292==    by 0x40682E: main_loop (ovsdb-server.c:209)
==5292==    by 0x40682E: main (ovsdb-server.c:460)
==5292==
==5292== LEAK SUMMARY:
==5292==    definitely lost: 1,472 bytes in 8 blocks
==5292==    indirectly lost: 48,248 bytes in 936 blocks
==5292==      possibly lost: 0 bytes in 0 blocks
==5292==    still reachable: 114,298 bytes in 3,308 blocks
==5292==         suppressed: 0 bytes in 0 blocks
==5292== Reachable blocks (those to which a pointer was found) are not shown.
==5292== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5292==
==5292== For counts of detected and suppressed errors, rerun with: -v
==5292== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 1 from 1)
....

In this case ovsdb-server is running as daemon process (--detach option) and leaking memory is
accumulated whenever ovsdb-client is reconnected. Within observed test ovsdb-client CLI tool
connects 8 times to ovsdb-server. Leaked memory in ovsdb-client (for each invocation) is approx.
6K bytes, while leaked memory in ovsdb-server is aprox. 48Kbytes what is actually 8*6K. Thus per
each connection both ovsdb-client and ovsdb-server leak approx. 6K bytes.

I have done a small manual test to check if ovsdb-server is indeed accumulating leaked memory
by dumping ovsdb-server in a loop:

console1:
ovsdb-server \
--log-file \
--detach --no-chdir --pidfile \
--private-key=testpki-privkey2.pem \
--certificate=testpki-cert2.pem \
--ca-cert=testpki-cacert.pem \
--remote=pssl:0:127.0.0.1 \
db

while (true); do \
ovsdb-client \
--private-key=testpki-privkey.pem \
--certificate=testpki-cert.pem \
--ca-cert=testpki-cacert.pem \
dump ssl:127.0.0.1:42067; \
done

console2:
watch -n 0.5 'cat /proc/$(pidof ovsdb-server)/status | grep VmSize'

In console2 it was evidently seen ovsdb-server is constantly leaking memory. After a while
(i.e. after a certain number of reconnections) the OOM killer jumps out and kills ovsdb-server.

Very similar situation was already noticed and described in
openvswitch/ovs-issues#168. There, the problem pops up while connecting
controller to ovs-vswitchd daemon.

Valgrind reports point to a problem in openssl library, however after studying openssl code for
a while I have found out the problem is actually in ovs. When connection through SSL channel is
taken place openssl library allocates memory for keeping track of certificate. Reference to this
memory works very similar as std::shared_ptr pointer in recent C++ dialects. i.e. when allocated
memory is referenced its reference counter is incremented and decremented after the memory is
derefered. When reference counter becomes zero allocated memory is automatically deallocated.

In openssl library environment certificate is retrieved by calling SSL_get_peer_certificate()
where its reference counter is incremented. After retrieved certificate is not used any more its
reference counter must be decremented by calling X509_free(). If not, allocated memory is never
freed despite the ssl connection is properly closed.

The problem was caused in stream-ssl.c in function ssl_connect(), which retrieves common peer name
by calling SSL_get_peer_certificate() function and without calling X509_free() function afterwards.

Signed-off-by: Damijan Skvarc <damjan.skvarc@gmail.com>
Signed-off-by: Ben Pfaff <blp@ovn.org>
blp pushed a commit to openvswitch/ovs that referenced this issue Sep 23, 2019
While checking valgrind reports after running "make check-valgrind" I have noticed
reports for several tests similar to the following:

....
==5345== Memcheck, a memory error detector
==5345== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5345== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5345== Command: ovsdb-client --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem transact ssl:127.0.0.1:40111 \ \ \ ["ordinals",
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["number",\ "==",\ 1]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 2,\ "name":\ "old\ two"}},
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["name",\ "==",\ "two"]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 1,\ "name":\ "old\ one"}}]
==5345== Parent PID: 5344
==5345==
==5345==
==5345== HEAP SUMMARY:
==5345==     in use at exit: 116,551 bytes in 3,341 blocks
==5345==   total heap usage: 5,134 allocs, 1,793 frees, 412,290 bytes allocated
==5345==
==5345== 6,221 (184 direct, 6,037 indirect) bytes in 1 blocks are definitely lost in loss record 498 of 500
==5345==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5345==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x4E56B27: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E5BA11: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E65145: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4522DF: ssl_connect (stream-ssl.c:530)
==5345==    by 0x443D38: scs_connecting (stream.c:315)
==5345==    by 0x443D38: stream_connect (stream.c:338)
==5345==    by 0x443FA1: stream_open_block (stream.c:266)
==5345==    by 0x40AB79: open_jsonrpc (ovsdb-client.c:507)
==5345==    by 0x40AB79: open_rpc (ovsdb-client.c:143)
==5345==    by 0x40B06B: do_transact__ (ovsdb-client.c:871)
==5345==    by 0x40B245: do_transact (ovsdb-client.c:893)
==5345==    by 0x405F76: main (ovsdb-client.c:282)
==5345==
==5345== LEAK SUMMARY:
==5345==    definitely lost: 184 bytes in 1 blocks
==5345==    indirectly lost: 6,037 bytes in 117 blocks
==5345==      possibly lost: 0 bytes in 0 blocks
==5345==    still reachable: 110,330 bytes in 3,223 blocks
==5345==         suppressed: 0 bytes in 0 blocks
==5345== Reachable blocks (those to which a pointer was found) are not shown.
==5345== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5345==
==5345== For counts of detected and suppressed errors, rerun with: -v
==5345== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0)
....

This report was extracted from "index uniqueness checking" test and complains about
leaking memory in ovsdb-client application. The problem is not huge, since ovsdb-client
is CLI tool which is constantly reinvoked/restarted, thus leaked memory is not accumulated.

More problematic issue is that for the same test valgrind reports the similar problem also for
ovsdb-server:

....
==5290== Memcheck, a memory error detector
==5290== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5290== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5290== Command: ovsdb-server --log-file --detach --no-chdir --pidfile --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey2.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert2.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem --remote=pssl:0:127.0.0.1 db
==5290== Parent PID: 5289
==5290==
==5292== Warning: noted but unhandled ioctl 0x2403 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292== Warning: noted but unhandled ioctl 0x2400 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5290==
==5290== HEAP SUMMARY:
==5290==     in use at exit: 2,066 bytes in 48 blocks
==5290==   total heap usage: 87 allocs, 39 frees, 14,152 bytes allocated
==5290==
==5290== LEAK SUMMARY:
==5290==    definitely lost: 0 bytes in 0 blocks
==5290==    indirectly lost: 0 bytes in 0 blocks
==5290==      possibly lost: 0 bytes in 0 blocks
==5290==    still reachable: 2,066 bytes in 48 blocks
==5290==         suppressed: 0 bytes in 0 blocks
==5290== Reachable blocks (those to which a pointer was found) are not shown.
==5290== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5290==
==5290== For counts of detected and suppressed errors, rerun with: -v
==5290== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 1 from 1)
==5292== Warning: noted but unhandled ioctl 0x2401 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292==
==5292== HEAP SUMMARY:
==5292==     in use at exit: 164,018 bytes in 4,252 blocks
==5292==   total heap usage: 17,910 allocs, 13,658 frees, 1,907,468 bytes allocated
==5292==
==5292== 49,720 (1,472 direct, 48,248 indirect) bytes in 8 blocks are definitely lost in loss record 580 of 580
==5292==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5292==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x4E53E00: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x4E55727: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x452C4B: ssl_connect (stream-ssl.c:530)
==5292==    by 0x445B18: scs_connecting (stream.c:315)
==5292==    by 0x445B18: stream_connect (stream.c:338)
==5292==    by 0x445B91: stream_recv (stream.c:369)
==5292==    by 0x432A9C: jsonrpc_recv.part.7 (jsonrpc.c:310)
==5292==    by 0x433977: jsonrpc_recv (jsonrpc.c:1139)
==5292==    by 0x433977: jsonrpc_session_recv (jsonrpc.c:1112)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run (jsonrpc-server.c:553)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run_all (jsonrpc-server.c:586)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_server_run (jsonrpc-server.c:401)
==5292==    by 0x40682E: main_loop (ovsdb-server.c:209)
==5292==    by 0x40682E: main (ovsdb-server.c:460)
==5292==
==5292== LEAK SUMMARY:
==5292==    definitely lost: 1,472 bytes in 8 blocks
==5292==    indirectly lost: 48,248 bytes in 936 blocks
==5292==      possibly lost: 0 bytes in 0 blocks
==5292==    still reachable: 114,298 bytes in 3,308 blocks
==5292==         suppressed: 0 bytes in 0 blocks
==5292== Reachable blocks (those to which a pointer was found) are not shown.
==5292== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5292==
==5292== For counts of detected and suppressed errors, rerun with: -v
==5292== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 1 from 1)
....

In this case ovsdb-server is running as daemon process (--detach option) and leaking memory is
accumulated whenever ovsdb-client is reconnected. Within observed test ovsdb-client CLI tool
connects 8 times to ovsdb-server. Leaked memory in ovsdb-client (for each invocation) is approx.
6K bytes, while leaked memory in ovsdb-server is aprox. 48Kbytes what is actually 8*6K. Thus per
each connection both ovsdb-client and ovsdb-server leak approx. 6K bytes.

I have done a small manual test to check if ovsdb-server is indeed accumulating leaked memory
by dumping ovsdb-server in a loop:

console1:
ovsdb-server \
--log-file \
--detach --no-chdir --pidfile \
--private-key=testpki-privkey2.pem \
--certificate=testpki-cert2.pem \
--ca-cert=testpki-cacert.pem \
--remote=pssl:0:127.0.0.1 \
db

while (true); do \
ovsdb-client \
--private-key=testpki-privkey.pem \
--certificate=testpki-cert.pem \
--ca-cert=testpki-cacert.pem \
dump ssl:127.0.0.1:42067; \
done

console2:
watch -n 0.5 'cat /proc/$(pidof ovsdb-server)/status | grep VmSize'

In console2 it was evidently seen ovsdb-server is constantly leaking memory. After a while
(i.e. after a certain number of reconnections) the OOM killer jumps out and kills ovsdb-server.

Very similar situation was already noticed and described in
openvswitch/ovs-issues#168. There, the problem pops up while connecting
controller to ovs-vswitchd daemon.

Valgrind reports point to a problem in openssl library, however after studying openssl code for
a while I have found out the problem is actually in ovs. When connection through SSL channel is
taken place openssl library allocates memory for keeping track of certificate. Reference to this
memory works very similar as std::shared_ptr pointer in recent C++ dialects. i.e. when allocated
memory is referenced its reference counter is incremented and decremented after the memory is
derefered. When reference counter becomes zero allocated memory is automatically deallocated.

In openssl library environment certificate is retrieved by calling SSL_get_peer_certificate()
where its reference counter is incremented. After retrieved certificate is not used any more its
reference counter must be decremented by calling X509_free(). If not, allocated memory is never
freed despite the ssl connection is properly closed.

The problem was caused in stream-ssl.c in function ssl_connect(), which retrieves common peer name
by calling SSL_get_peer_certificate() function and without calling X509_free() function afterwards.

Signed-off-by: Damijan Skvarc <damjan.skvarc@gmail.com>
Signed-off-by: Ben Pfaff <blp@ovn.org>
blp pushed a commit to openvswitch/ovs that referenced this issue Sep 23, 2019
While checking valgrind reports after running "make check-valgrind" I have noticed
reports for several tests similar to the following:

....
==5345== Memcheck, a memory error detector
==5345== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5345== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5345== Command: ovsdb-client --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem transact ssl:127.0.0.1:40111 \ \ \ ["ordinals",
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["number",\ "==",\ 1]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 2,\ "name":\ "old\ two"}},
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["name",\ "==",\ "two"]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 1,\ "name":\ "old\ one"}}]
==5345== Parent PID: 5344
==5345==
==5345==
==5345== HEAP SUMMARY:
==5345==     in use at exit: 116,551 bytes in 3,341 blocks
==5345==   total heap usage: 5,134 allocs, 1,793 frees, 412,290 bytes allocated
==5345==
==5345== 6,221 (184 direct, 6,037 indirect) bytes in 1 blocks are definitely lost in loss record 498 of 500
==5345==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5345==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x4E56B27: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E5BA11: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E65145: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4522DF: ssl_connect (stream-ssl.c:530)
==5345==    by 0x443D38: scs_connecting (stream.c:315)
==5345==    by 0x443D38: stream_connect (stream.c:338)
==5345==    by 0x443FA1: stream_open_block (stream.c:266)
==5345==    by 0x40AB79: open_jsonrpc (ovsdb-client.c:507)
==5345==    by 0x40AB79: open_rpc (ovsdb-client.c:143)
==5345==    by 0x40B06B: do_transact__ (ovsdb-client.c:871)
==5345==    by 0x40B245: do_transact (ovsdb-client.c:893)
==5345==    by 0x405F76: main (ovsdb-client.c:282)
==5345==
==5345== LEAK SUMMARY:
==5345==    definitely lost: 184 bytes in 1 blocks
==5345==    indirectly lost: 6,037 bytes in 117 blocks
==5345==      possibly lost: 0 bytes in 0 blocks
==5345==    still reachable: 110,330 bytes in 3,223 blocks
==5345==         suppressed: 0 bytes in 0 blocks
==5345== Reachable blocks (those to which a pointer was found) are not shown.
==5345== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5345==
==5345== For counts of detected and suppressed errors, rerun with: -v
==5345== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0)
....

This report was extracted from "index uniqueness checking" test and complains about
leaking memory in ovsdb-client application. The problem is not huge, since ovsdb-client
is CLI tool which is constantly reinvoked/restarted, thus leaked memory is not accumulated.

More problematic issue is that for the same test valgrind reports the similar problem also for
ovsdb-server:

....
==5290== Memcheck, a memory error detector
==5290== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5290== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5290== Command: ovsdb-server --log-file --detach --no-chdir --pidfile --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey2.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert2.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem --remote=pssl:0:127.0.0.1 db
==5290== Parent PID: 5289
==5290==
==5292== Warning: noted but unhandled ioctl 0x2403 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292== Warning: noted but unhandled ioctl 0x2400 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5290==
==5290== HEAP SUMMARY:
==5290==     in use at exit: 2,066 bytes in 48 blocks
==5290==   total heap usage: 87 allocs, 39 frees, 14,152 bytes allocated
==5290==
==5290== LEAK SUMMARY:
==5290==    definitely lost: 0 bytes in 0 blocks
==5290==    indirectly lost: 0 bytes in 0 blocks
==5290==      possibly lost: 0 bytes in 0 blocks
==5290==    still reachable: 2,066 bytes in 48 blocks
==5290==         suppressed: 0 bytes in 0 blocks
==5290== Reachable blocks (those to which a pointer was found) are not shown.
==5290== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5290==
==5290== For counts of detected and suppressed errors, rerun with: -v
==5290== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 1 from 1)
==5292== Warning: noted but unhandled ioctl 0x2401 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292==
==5292== HEAP SUMMARY:
==5292==     in use at exit: 164,018 bytes in 4,252 blocks
==5292==   total heap usage: 17,910 allocs, 13,658 frees, 1,907,468 bytes allocated
==5292==
==5292== 49,720 (1,472 direct, 48,248 indirect) bytes in 8 blocks are definitely lost in loss record 580 of 580
==5292==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5292==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x4E53E00: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x4E55727: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x452C4B: ssl_connect (stream-ssl.c:530)
==5292==    by 0x445B18: scs_connecting (stream.c:315)
==5292==    by 0x445B18: stream_connect (stream.c:338)
==5292==    by 0x445B91: stream_recv (stream.c:369)
==5292==    by 0x432A9C: jsonrpc_recv.part.7 (jsonrpc.c:310)
==5292==    by 0x433977: jsonrpc_recv (jsonrpc.c:1139)
==5292==    by 0x433977: jsonrpc_session_recv (jsonrpc.c:1112)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run (jsonrpc-server.c:553)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run_all (jsonrpc-server.c:586)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_server_run (jsonrpc-server.c:401)
==5292==    by 0x40682E: main_loop (ovsdb-server.c:209)
==5292==    by 0x40682E: main (ovsdb-server.c:460)
==5292==
==5292== LEAK SUMMARY:
==5292==    definitely lost: 1,472 bytes in 8 blocks
==5292==    indirectly lost: 48,248 bytes in 936 blocks
==5292==      possibly lost: 0 bytes in 0 blocks
==5292==    still reachable: 114,298 bytes in 3,308 blocks
==5292==         suppressed: 0 bytes in 0 blocks
==5292== Reachable blocks (those to which a pointer was found) are not shown.
==5292== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5292==
==5292== For counts of detected and suppressed errors, rerun with: -v
==5292== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 1 from 1)
....

In this case ovsdb-server is running as daemon process (--detach option) and leaking memory is
accumulated whenever ovsdb-client is reconnected. Within observed test ovsdb-client CLI tool
connects 8 times to ovsdb-server. Leaked memory in ovsdb-client (for each invocation) is approx.
6K bytes, while leaked memory in ovsdb-server is aprox. 48Kbytes what is actually 8*6K. Thus per
each connection both ovsdb-client and ovsdb-server leak approx. 6K bytes.

I have done a small manual test to check if ovsdb-server is indeed accumulating leaked memory
by dumping ovsdb-server in a loop:

console1:
ovsdb-server \
--log-file \
--detach --no-chdir --pidfile \
--private-key=testpki-privkey2.pem \
--certificate=testpki-cert2.pem \
--ca-cert=testpki-cacert.pem \
--remote=pssl:0:127.0.0.1 \
db

while (true); do \
ovsdb-client \
--private-key=testpki-privkey.pem \
--certificate=testpki-cert.pem \
--ca-cert=testpki-cacert.pem \
dump ssl:127.0.0.1:42067; \
done

console2:
watch -n 0.5 'cat /proc/$(pidof ovsdb-server)/status | grep VmSize'

In console2 it was evidently seen ovsdb-server is constantly leaking memory. After a while
(i.e. after a certain number of reconnections) the OOM killer jumps out and kills ovsdb-server.

Very similar situation was already noticed and described in
openvswitch/ovs-issues#168. There, the problem pops up while connecting
controller to ovs-vswitchd daemon.

Valgrind reports point to a problem in openssl library, however after studying openssl code for
a while I have found out the problem is actually in ovs. When connection through SSL channel is
taken place openssl library allocates memory for keeping track of certificate. Reference to this
memory works very similar as std::shared_ptr pointer in recent C++ dialects. i.e. when allocated
memory is referenced its reference counter is incremented and decremented after the memory is
derefered. When reference counter becomes zero allocated memory is automatically deallocated.

In openssl library environment certificate is retrieved by calling SSL_get_peer_certificate()
where its reference counter is incremented. After retrieved certificate is not used any more its
reference counter must be decremented by calling X509_free(). If not, allocated memory is never
freed despite the ssl connection is properly closed.

The problem was caused in stream-ssl.c in function ssl_connect(), which retrieves common peer name
by calling SSL_get_peer_certificate() function and without calling X509_free() function afterwards.

Signed-off-by: Damijan Skvarc <damjan.skvarc@gmail.com>
Signed-off-by: Ben Pfaff <blp@ovn.org>
LorenzoBianconi pushed a commit to LorenzoBianconi/ovs that referenced this issue Oct 4, 2019
While checking valgrind reports after running "make check-valgrind" I have noticed
reports for several tests similar to the following:

....
==5345== Memcheck, a memory error detector
==5345== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5345== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5345== Command: ovsdb-client --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem transact ssl:127.0.0.1:40111 \ \ \ ["ordinals",
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["number",\ "==",\ 1]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 2,\ "name":\ "old\ two"}},
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["name",\ "==",\ "two"]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 1,\ "name":\ "old\ one"}}]
==5345== Parent PID: 5344
==5345==
==5345==
==5345== HEAP SUMMARY:
==5345==     in use at exit: 116,551 bytes in 3,341 blocks
==5345==   total heap usage: 5,134 allocs, 1,793 frees, 412,290 bytes allocated
==5345==
==5345== 6,221 (184 direct, 6,037 indirect) bytes in 1 blocks are definitely lost in loss record 498 of 500
==5345==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5345==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x4E56B27: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E5BA11: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E65145: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4522DF: ssl_connect (stream-ssl.c:530)
==5345==    by 0x443D38: scs_connecting (stream.c:315)
==5345==    by 0x443D38: stream_connect (stream.c:338)
==5345==    by 0x443FA1: stream_open_block (stream.c:266)
==5345==    by 0x40AB79: open_jsonrpc (ovsdb-client.c:507)
==5345==    by 0x40AB79: open_rpc (ovsdb-client.c:143)
==5345==    by 0x40B06B: do_transact__ (ovsdb-client.c:871)
==5345==    by 0x40B245: do_transact (ovsdb-client.c:893)
==5345==    by 0x405F76: main (ovsdb-client.c:282)
==5345==
==5345== LEAK SUMMARY:
==5345==    definitely lost: 184 bytes in 1 blocks
==5345==    indirectly lost: 6,037 bytes in 117 blocks
==5345==      possibly lost: 0 bytes in 0 blocks
==5345==    still reachable: 110,330 bytes in 3,223 blocks
==5345==         suppressed: 0 bytes in 0 blocks
==5345== Reachable blocks (those to which a pointer was found) are not shown.
==5345== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5345==
==5345== For counts of detected and suppressed errors, rerun with: -v
==5345== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0)
....

This report was extracted from "index uniqueness checking" test and complains about
leaking memory in ovsdb-client application. The problem is not huge, since ovsdb-client
is CLI tool which is constantly reinvoked/restarted, thus leaked memory is not accumulated.

More problematic issue is that for the same test valgrind reports the similar problem also for
ovsdb-server:

....
==5290== Memcheck, a memory error detector
==5290== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5290== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5290== Command: ovsdb-server --log-file --detach --no-chdir --pidfile --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey2.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert2.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem --remote=pssl:0:127.0.0.1 db
==5290== Parent PID: 5289
==5290==
==5292== Warning: noted but unhandled ioctl 0x2403 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292== Warning: noted but unhandled ioctl 0x2400 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5290==
==5290== HEAP SUMMARY:
==5290==     in use at exit: 2,066 bytes in 48 blocks
==5290==   total heap usage: 87 allocs, 39 frees, 14,152 bytes allocated
==5290==
==5290== LEAK SUMMARY:
==5290==    definitely lost: 0 bytes in 0 blocks
==5290==    indirectly lost: 0 bytes in 0 blocks
==5290==      possibly lost: 0 bytes in 0 blocks
==5290==    still reachable: 2,066 bytes in 48 blocks
==5290==         suppressed: 0 bytes in 0 blocks
==5290== Reachable blocks (those to which a pointer was found) are not shown.
==5290== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5290==
==5290== For counts of detected and suppressed errors, rerun with: -v
==5290== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 1 from 1)
==5292== Warning: noted but unhandled ioctl 0x2401 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292==
==5292== HEAP SUMMARY:
==5292==     in use at exit: 164,018 bytes in 4,252 blocks
==5292==   total heap usage: 17,910 allocs, 13,658 frees, 1,907,468 bytes allocated
==5292==
==5292== 49,720 (1,472 direct, 48,248 indirect) bytes in 8 blocks are definitely lost in loss record 580 of 580
==5292==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5292==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x4E53E00: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x4E55727: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x452C4B: ssl_connect (stream-ssl.c:530)
==5292==    by 0x445B18: scs_connecting (stream.c:315)
==5292==    by 0x445B18: stream_connect (stream.c:338)
==5292==    by 0x445B91: stream_recv (stream.c:369)
==5292==    by 0x432A9C: jsonrpc_recv.part.7 (jsonrpc.c:310)
==5292==    by 0x433977: jsonrpc_recv (jsonrpc.c:1139)
==5292==    by 0x433977: jsonrpc_session_recv (jsonrpc.c:1112)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run (jsonrpc-server.c:553)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run_all (jsonrpc-server.c:586)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_server_run (jsonrpc-server.c:401)
==5292==    by 0x40682E: main_loop (ovsdb-server.c:209)
==5292==    by 0x40682E: main (ovsdb-server.c:460)
==5292==
==5292== LEAK SUMMARY:
==5292==    definitely lost: 1,472 bytes in 8 blocks
==5292==    indirectly lost: 48,248 bytes in 936 blocks
==5292==      possibly lost: 0 bytes in 0 blocks
==5292==    still reachable: 114,298 bytes in 3,308 blocks
==5292==         suppressed: 0 bytes in 0 blocks
==5292== Reachable blocks (those to which a pointer was found) are not shown.
==5292== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5292==
==5292== For counts of detected and suppressed errors, rerun with: -v
==5292== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 1 from 1)
....

In this case ovsdb-server is running as daemon process (--detach option) and leaking memory is
accumulated whenever ovsdb-client is reconnected. Within observed test ovsdb-client CLI tool
connects 8 times to ovsdb-server. Leaked memory in ovsdb-client (for each invocation) is approx.
6K bytes, while leaked memory in ovsdb-server is aprox. 48Kbytes what is actually 8*6K. Thus per
each connection both ovsdb-client and ovsdb-server leak approx. 6K bytes.

I have done a small manual test to check if ovsdb-server is indeed accumulating leaked memory
by dumping ovsdb-server in a loop:

console1:
ovsdb-server \
--log-file \
--detach --no-chdir --pidfile \
--private-key=testpki-privkey2.pem \
--certificate=testpki-cert2.pem \
--ca-cert=testpki-cacert.pem \
--remote=pssl:0:127.0.0.1 \
db

while (true); do \
ovsdb-client \
--private-key=testpki-privkey.pem \
--certificate=testpki-cert.pem \
--ca-cert=testpki-cacert.pem \
dump ssl:127.0.0.1:42067; \
done

console2:
watch -n 0.5 'cat /proc/$(pidof ovsdb-server)/status | grep VmSize'

In console2 it was evidently seen ovsdb-server is constantly leaking memory. After a while
(i.e. after a certain number of reconnections) the OOM killer jumps out and kills ovsdb-server.

Very similar situation was already noticed and described in
openvswitch/ovs-issues#168. There, the problem pops up while connecting
controller to ovs-vswitchd daemon.

Valgrind reports point to a problem in openssl library, however after studying openssl code for
a while I have found out the problem is actually in ovs. When connection through SSL channel is
taken place openssl library allocates memory for keeping track of certificate. Reference to this
memory works very similar as std::shared_ptr pointer in recent C++ dialects. i.e. when allocated
memory is referenced its reference counter is incremented and decremented after the memory is
derefered. When reference counter becomes zero allocated memory is automatically deallocated.

In openssl library environment certificate is retrieved by calling SSL_get_peer_certificate()
where its reference counter is incremented. After retrieved certificate is not used any more its
reference counter must be decremented by calling X509_free(). If not, allocated memory is never
freed despite the ssl connection is properly closed.

The problem was caused in stream-ssl.c in function ssl_connect(), which retrieves common peer name
by calling SSL_get_peer_certificate() function and without calling X509_free() function afterwards.

Signed-off-by: Damijan Skvarc <damjan.skvarc@gmail.com>
Signed-off-by: Ben Pfaff <blp@ovn.org>
LorenzoBianconi pushed a commit to LorenzoBianconi/ovs that referenced this issue Oct 10, 2019
While checking valgrind reports after running "make check-valgrind" I have noticed
reports for several tests similar to the following:

....
==5345== Memcheck, a memory error detector
==5345== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5345== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5345== Command: ovsdb-client --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem transact ssl:127.0.0.1:40111 \ \ \ ["ordinals",
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["number",\ "==",\ 1]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 2,\ "name":\ "old\ two"}},
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["name",\ "==",\ "two"]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 1,\ "name":\ "old\ one"}}]
==5345== Parent PID: 5344
==5345==
==5345==
==5345== HEAP SUMMARY:
==5345==     in use at exit: 116,551 bytes in 3,341 blocks
==5345==   total heap usage: 5,134 allocs, 1,793 frees, 412,290 bytes allocated
==5345==
==5345== 6,221 (184 direct, 6,037 indirect) bytes in 1 blocks are definitely lost in loss record 498 of 500
==5345==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5345==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x4E56B27: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E5BA11: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E65145: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4522DF: ssl_connect (stream-ssl.c:530)
==5345==    by 0x443D38: scs_connecting (stream.c:315)
==5345==    by 0x443D38: stream_connect (stream.c:338)
==5345==    by 0x443FA1: stream_open_block (stream.c:266)
==5345==    by 0x40AB79: open_jsonrpc (ovsdb-client.c:507)
==5345==    by 0x40AB79: open_rpc (ovsdb-client.c:143)
==5345==    by 0x40B06B: do_transact__ (ovsdb-client.c:871)
==5345==    by 0x40B245: do_transact (ovsdb-client.c:893)
==5345==    by 0x405F76: main (ovsdb-client.c:282)
==5345==
==5345== LEAK SUMMARY:
==5345==    definitely lost: 184 bytes in 1 blocks
==5345==    indirectly lost: 6,037 bytes in 117 blocks
==5345==      possibly lost: 0 bytes in 0 blocks
==5345==    still reachable: 110,330 bytes in 3,223 blocks
==5345==         suppressed: 0 bytes in 0 blocks
==5345== Reachable blocks (those to which a pointer was found) are not shown.
==5345== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5345==
==5345== For counts of detected and suppressed errors, rerun with: -v
==5345== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0)
....

This report was extracted from "index uniqueness checking" test and complains about
leaking memory in ovsdb-client application. The problem is not huge, since ovsdb-client
is CLI tool which is constantly reinvoked/restarted, thus leaked memory is not accumulated.

More problematic issue is that for the same test valgrind reports the similar problem also for
ovsdb-server:

....
==5290== Memcheck, a memory error detector
==5290== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5290== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5290== Command: ovsdb-server --log-file --detach --no-chdir --pidfile --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey2.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert2.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem --remote=pssl:0:127.0.0.1 db
==5290== Parent PID: 5289
==5290==
==5292== Warning: noted but unhandled ioctl 0x2403 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292== Warning: noted but unhandled ioctl 0x2400 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5290==
==5290== HEAP SUMMARY:
==5290==     in use at exit: 2,066 bytes in 48 blocks
==5290==   total heap usage: 87 allocs, 39 frees, 14,152 bytes allocated
==5290==
==5290== LEAK SUMMARY:
==5290==    definitely lost: 0 bytes in 0 blocks
==5290==    indirectly lost: 0 bytes in 0 blocks
==5290==      possibly lost: 0 bytes in 0 blocks
==5290==    still reachable: 2,066 bytes in 48 blocks
==5290==         suppressed: 0 bytes in 0 blocks
==5290== Reachable blocks (those to which a pointer was found) are not shown.
==5290== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5290==
==5290== For counts of detected and suppressed errors, rerun with: -v
==5290== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 1 from 1)
==5292== Warning: noted but unhandled ioctl 0x2401 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292==
==5292== HEAP SUMMARY:
==5292==     in use at exit: 164,018 bytes in 4,252 blocks
==5292==   total heap usage: 17,910 allocs, 13,658 frees, 1,907,468 bytes allocated
==5292==
==5292== 49,720 (1,472 direct, 48,248 indirect) bytes in 8 blocks are definitely lost in loss record 580 of 580
==5292==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5292==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x4E53E00: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x4E55727: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x452C4B: ssl_connect (stream-ssl.c:530)
==5292==    by 0x445B18: scs_connecting (stream.c:315)
==5292==    by 0x445B18: stream_connect (stream.c:338)
==5292==    by 0x445B91: stream_recv (stream.c:369)
==5292==    by 0x432A9C: jsonrpc_recv.part.7 (jsonrpc.c:310)
==5292==    by 0x433977: jsonrpc_recv (jsonrpc.c:1139)
==5292==    by 0x433977: jsonrpc_session_recv (jsonrpc.c:1112)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run (jsonrpc-server.c:553)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run_all (jsonrpc-server.c:586)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_server_run (jsonrpc-server.c:401)
==5292==    by 0x40682E: main_loop (ovsdb-server.c:209)
==5292==    by 0x40682E: main (ovsdb-server.c:460)
==5292==
==5292== LEAK SUMMARY:
==5292==    definitely lost: 1,472 bytes in 8 blocks
==5292==    indirectly lost: 48,248 bytes in 936 blocks
==5292==      possibly lost: 0 bytes in 0 blocks
==5292==    still reachable: 114,298 bytes in 3,308 blocks
==5292==         suppressed: 0 bytes in 0 blocks
==5292== Reachable blocks (those to which a pointer was found) are not shown.
==5292== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5292==
==5292== For counts of detected and suppressed errors, rerun with: -v
==5292== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 1 from 1)
....

In this case ovsdb-server is running as daemon process (--detach option) and leaking memory is
accumulated whenever ovsdb-client is reconnected. Within observed test ovsdb-client CLI tool
connects 8 times to ovsdb-server. Leaked memory in ovsdb-client (for each invocation) is approx.
6K bytes, while leaked memory in ovsdb-server is aprox. 48Kbytes what is actually 8*6K. Thus per
each connection both ovsdb-client and ovsdb-server leak approx. 6K bytes.

I have done a small manual test to check if ovsdb-server is indeed accumulating leaked memory
by dumping ovsdb-server in a loop:

console1:
ovsdb-server \
--log-file \
--detach --no-chdir --pidfile \
--private-key=testpki-privkey2.pem \
--certificate=testpki-cert2.pem \
--ca-cert=testpki-cacert.pem \
--remote=pssl:0:127.0.0.1 \
db

while (true); do \
ovsdb-client \
--private-key=testpki-privkey.pem \
--certificate=testpki-cert.pem \
--ca-cert=testpki-cacert.pem \
dump ssl:127.0.0.1:42067; \
done

console2:
watch -n 0.5 'cat /proc/$(pidof ovsdb-server)/status | grep VmSize'

In console2 it was evidently seen ovsdb-server is constantly leaking memory. After a while
(i.e. after a certain number of reconnections) the OOM killer jumps out and kills ovsdb-server.

Very similar situation was already noticed and described in
openvswitch/ovs-issues#168. There, the problem pops up while connecting
controller to ovs-vswitchd daemon.

Valgrind reports point to a problem in openssl library, however after studying openssl code for
a while I have found out the problem is actually in ovs. When connection through SSL channel is
taken place openssl library allocates memory for keeping track of certificate. Reference to this
memory works very similar as std::shared_ptr pointer in recent C++ dialects. i.e. when allocated
memory is referenced its reference counter is incremented and decremented after the memory is
derefered. When reference counter becomes zero allocated memory is automatically deallocated.

In openssl library environment certificate is retrieved by calling SSL_get_peer_certificate()
where its reference counter is incremented. After retrieved certificate is not used any more its
reference counter must be decremented by calling X509_free(). If not, allocated memory is never
freed despite the ssl connection is properly closed.

The problem was caused in stream-ssl.c in function ssl_connect(), which retrieves common peer name
by calling SSL_get_peer_certificate() function and without calling X509_free() function afterwards.

Signed-off-by: Damijan Skvarc <damjan.skvarc@gmail.com>
Signed-off-by: Ben Pfaff <blp@ovn.org>
@casasfernando
Copy link
Author

casasfernando commented May 1, 2020

Hi there,

I'm now running on version 2.12.0 and the problem remains the same.
As a workaround I have a watchdog script running that checks ovs-vswitchd memory usage and restart the service when it's using more than 500MB.

If there is any information or help I can provide to find and fix this issue let me know.

Thanks.

@casasfernando casasfernando changed the title ovs-vswitchd: possible memory leak in 2.10.1 ovs-vswitchd: possible memory leak in 2.12.0 (issue is happening since 2.10.1 at least) May 1, 2020
@damijans
Copy link

damijans commented May 4, 2020

I am sorry the fix described in https://mail.openvswitch.org/pipermail/ovs-dev/2019-July/361062.html didn't solve your issue. Probably it was more related to #168 (comment) and #168 (comment) issues from which descriptions it was possible to deduce the problem was in the establishment of communication with ovs-vswitchd daemon. For the proper solution it is the most important to reproduce the issue properly. So, it would be nice if you could describe your use case in more detail.

Also, it is possible that we are not talking about memory leak but about huge memory consumption which depends on variety of different traffic flows. Unfortunately, I am not the expert in functionality of ovs-vswithcd and I can only predict about possibility to limit memory consumption. There are a couple of experts (for example ben, dumitru, michelson, ilya, wiliamtu...) who I belive can tell you more about this.

Anyway, if you can depict in more detail about your use case I am willing to dig again into this issue.

@igsilya
Copy link
Member

igsilya commented May 4, 2020

I'm now running on version 2.12.0 and the problem remains the same.

Hi. The commit "stream_ssl: fix important memory leak in ssl_connect() function" from @damijans is not in v2.12.0 release. @casasfernando, Could you try building from branch-2.12 and not from the v2.12.0 tag?

@williamtu
Copy link

williamtu commented May 4, 2020

Hi,
Providing the memory dump (or coredump file) is also useful. If you can put it somewhere for us to download. We used to analyze it with chap
https://github.com/vmware/chap

@casasfernando
Copy link
Author

casasfernando commented May 4, 2020

I am sorry the fix described in https://mail.openvswitch.org/pipermail/ovs-dev/2019-July/361062.html didn't solve your issue. Probably it was more related to #168 (comment) and #168 (comment) issues from which descriptions it was possible to deduce the problem was in the establishment of communication with ovs-vswitchd daemon. For the proper solution it is the most important to reproduce the issue properly. So, it would be nice if you could describe your use case in more detail.

Also, it is possible that we are not talking about memory leak but about huge memory consumption which depends on variety of different traffic flows. Unfortunately, I am not the expert in functionality of ovs-vswithcd and I can only predict about possibility to limit memory consumption. There are a couple of experts (for example ben, dumitru, michelson, ilya, wiliamtu...) who I belive can tell you more about this.

Anyway, if you can depict in more detail about your use case I am willing to dig again into this issue.

Please, don't be. I only wanted to update the report since I also reported the same issue to Alpine Linux maintainers and the pinged me to confirm this was still happening today.
Having said that, based on another comment above is possible that I'm not even using a version with your patch applied.

Regarding the scenario, I think my original post is pretty much detailed so I'm not sure what else I can add to it. The scenario didn't change at all, except that nowadays I'm running on newer versions of the software that I will provide below:

OVS command line: /usr/sbin/ovs-vswitchd --pidfile=/var/run/openvswitch/ovs-vswitchd.pid --detach --monitor --mlockall unix:/var/run/openvswitch/db.sock
OVS version: 2.12.0
Distro: Alpine Linux 3.11.5
Linux kernel version: 5.4.27
Qemu version: 4.2.0
Libvirt version: 5.9.0

If there is any information that you feel it's missing in the issue description (1st post) don't hesitate to ask I will provide it.

Thanks.

@casasfernando
Copy link
Author

casasfernando commented May 4, 2020

Hi,
Providing the memory dump (or coredump file) is also useful. If you can put it somewhere for us to download. We used to analyze it with chap
https://github.com/vmware/chap

Last time I did share one with Ben but I can't remember if it helped or not. I still have that one around (with the binary including debug symbols) if it makes any sense to share it or I can try to create a new one with the current version instead (probably it makes more sense).
Just let me know.

@casasfernando
Copy link
Author

casasfernando commented May 4, 2020

I'm now running on version 2.12.0 and the problem remains the same.

Hi. The commit "stream_ssl: fix important memory leak in ssl_connect() function" from @damijans is not in v2.12.0 release. @casasfernando, Could you try building from branch-2.12 and not from the v2.12.0 tag?

Is not impossible to do, but certainly not easy at the moment.
Let me ask you. I see in github release page that there is already a 2.13.0 release tagged since last Feb. Is this one the new stable? I'm asking because Alpine usually ships the latest version with newer releases. So it's possible that in a couple of months when they release a newer Alpine version it will include a version of OVS with the fix included. I don't mind waiting until then to be honest, since right now with the watchdog script monitoring the process memory usage, everything is under control.

@williamtu
Copy link

williamtu commented May 4, 2020

Hi,
Providing the memory dump (or coredump file) is also useful. If you can put it somewhere for us to download. We used to analyze it with chap
https://github.com/vmware/chap

Last time I did share one with Ben but I can't remember if it helped or not. I still have that one around (with the binary including debug symbols) if it makes any sense to share it or I can try to create a new one with the current version instead (probably it makes more sense).
Just let me know.

chap will only show the leaked memory's size and content and the number of blocks leaked. Then we will have to guess what data structure in OVS it is, probably using pahole. And we will need much more information on your setup, ex: running a "ovs-bugtool -y". This is definitely not easy. If you want to wait for Alphine using latest OVS version, then that's also make sense.

aserdean pushed a commit to cloudbase/ovs that referenced this issue Jul 15, 2020
While checking valgrind reports after running "make check-valgrind" I have noticed
reports for several tests similar to the following:

....
==5345== Memcheck, a memory error detector
==5345== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5345== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5345== Command: ovsdb-client --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem transact ssl:127.0.0.1:40111 \ \ \ ["ordinals",
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["number",\ "==",\ 1]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 2,\ "name":\ "old\ two"}},
==5345== \ \ \ \ \ \ {"op":\ "update",
==5345== \ \ \ \ \ \ \ "table":\ "ordinals",
==5345== \ \ \ \ \ \ \ "where":\ [["name",\ "==",\ "two"]],
==5345== \ \ \ \ \ \ \ "row":\ {"number":\ 1,\ "name":\ "old\ one"}}]
==5345== Parent PID: 5344
==5345==
==5345==
==5345== HEAP SUMMARY:
==5345==     in use at exit: 116,551 bytes in 3,341 blocks
==5345==   total heap usage: 5,134 allocs, 1,793 frees, 412,290 bytes allocated
==5345==
==5345== 6,221 (184 direct, 6,037 indirect) bytes in 1 blocks are definitely lost in loss record 498 of 500
==5345==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5345==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5345==    by 0x4E56B27: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E5BA11: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4E65145: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5345==    by 0x4522DF: ssl_connect (stream-ssl.c:530)
==5345==    by 0x443D38: scs_connecting (stream.c:315)
==5345==    by 0x443D38: stream_connect (stream.c:338)
==5345==    by 0x443FA1: stream_open_block (stream.c:266)
==5345==    by 0x40AB79: open_jsonrpc (ovsdb-client.c:507)
==5345==    by 0x40AB79: open_rpc (ovsdb-client.c:143)
==5345==    by 0x40B06B: do_transact__ (ovsdb-client.c:871)
==5345==    by 0x40B245: do_transact (ovsdb-client.c:893)
==5345==    by 0x405F76: main (ovsdb-client.c:282)
==5345==
==5345== LEAK SUMMARY:
==5345==    definitely lost: 184 bytes in 1 blocks
==5345==    indirectly lost: 6,037 bytes in 117 blocks
==5345==      possibly lost: 0 bytes in 0 blocks
==5345==    still reachable: 110,330 bytes in 3,223 blocks
==5345==         suppressed: 0 bytes in 0 blocks
==5345== Reachable blocks (those to which a pointer was found) are not shown.
==5345== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5345==
==5345== For counts of detected and suppressed errors, rerun with: -v
==5345== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0)
....

This report was extracted from "index uniqueness checking" test and complains about
leaking memory in ovsdb-client application. The problem is not huge, since ovsdb-client
is CLI tool which is constantly reinvoked/restarted, thus leaked memory is not accumulated.

More problematic issue is that for the same test valgrind reports the similar problem also for
ovsdb-server:

....
==5290== Memcheck, a memory error detector
==5290== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==5290== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==5290== Command: ovsdb-server --log-file --detach --no-chdir --pidfile --private-key=/home/damijan.skvarc/doma/ovs/tests/testpki-privkey2.pem --certificate=/home/damijan.skvarc/doma/ovs/tests/testpki-cert2.pem --ca-cert=/home/damijan.skvarc/doma/ovs/tests/testpki-cacert.pem --remote=pssl:0:127.0.0.1 db
==5290== Parent PID: 5289
==5290==
==5292== Warning: noted but unhandled ioctl 0x2403 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292== Warning: noted but unhandled ioctl 0x2400 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5290==
==5290== HEAP SUMMARY:
==5290==     in use at exit: 2,066 bytes in 48 blocks
==5290==   total heap usage: 87 allocs, 39 frees, 14,152 bytes allocated
==5290==
==5290== LEAK SUMMARY:
==5290==    definitely lost: 0 bytes in 0 blocks
==5290==    indirectly lost: 0 bytes in 0 blocks
==5290==      possibly lost: 0 bytes in 0 blocks
==5290==    still reachable: 2,066 bytes in 48 blocks
==5290==         suppressed: 0 bytes in 0 blocks
==5290== Reachable blocks (those to which a pointer was found) are not shown.
==5290== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5290==
==5290== For counts of detected and suppressed errors, rerun with: -v
==5290== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 1 from 1)
==5292== Warning: noted but unhandled ioctl 0x2401 with no size/direction hints.
==5292==    This could cause spurious value errors to appear.
==5292==    See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
==5292==
==5292== HEAP SUMMARY:
==5292==     in use at exit: 164,018 bytes in 4,252 blocks
==5292==   total heap usage: 17,910 allocs, 13,658 frees, 1,907,468 bytes allocated
==5292==
==5292== 49,720 (1,472 direct, 48,248 indirect) bytes in 8 blocks are definitely lost in loss record 580 of 580
==5292==    at 0x4C2DB8F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5292==    by 0x5105E77: CRYPTO_malloc (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E1D23: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E4861: ??? (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E5414: ASN1_item_ex_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x51E546A: ASN1_item_d2i (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
==5292==    by 0x4E53E00: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x4E55727: ??? (in /lib/x86_64-linux-gnu/libssl.so.1.0.0)
==5292==    by 0x452C4B: ssl_connect (stream-ssl.c:530)
==5292==    by 0x445B18: scs_connecting (stream.c:315)
==5292==    by 0x445B18: stream_connect (stream.c:338)
==5292==    by 0x445B91: stream_recv (stream.c:369)
==5292==    by 0x432A9C: jsonrpc_recv.part.7 (jsonrpc.c:310)
==5292==    by 0x433977: jsonrpc_recv (jsonrpc.c:1139)
==5292==    by 0x433977: jsonrpc_session_recv (jsonrpc.c:1112)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run (jsonrpc-server.c:553)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_session_run_all (jsonrpc-server.c:586)
==5292==    by 0x40CCE3: ovsdb_jsonrpc_server_run (jsonrpc-server.c:401)
==5292==    by 0x40682E: main_loop (ovsdb-server.c:209)
==5292==    by 0x40682E: main (ovsdb-server.c:460)
==5292==
==5292== LEAK SUMMARY:
==5292==    definitely lost: 1,472 bytes in 8 blocks
==5292==    indirectly lost: 48,248 bytes in 936 blocks
==5292==      possibly lost: 0 bytes in 0 blocks
==5292==    still reachable: 114,298 bytes in 3,308 blocks
==5292==         suppressed: 0 bytes in 0 blocks
==5292== Reachable blocks (those to which a pointer was found) are not shown.
==5292== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5292==
==5292== For counts of detected and suppressed errors, rerun with: -v
==5292== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 1 from 1)
....

In this case ovsdb-server is running as daemon process (--detach option) and leaking memory is
accumulated whenever ovsdb-client is reconnected. Within observed test ovsdb-client CLI tool
connects 8 times to ovsdb-server. Leaked memory in ovsdb-client (for each invocation) is approx.
6K bytes, while leaked memory in ovsdb-server is aprox. 48Kbytes what is actually 8*6K. Thus per
each connection both ovsdb-client and ovsdb-server leak approx. 6K bytes.

I have done a small manual test to check if ovsdb-server is indeed accumulating leaked memory
by dumping ovsdb-server in a loop:

console1:
ovsdb-server \
--log-file \
--detach --no-chdir --pidfile \
--private-key=testpki-privkey2.pem \
--certificate=testpki-cert2.pem \
--ca-cert=testpki-cacert.pem \
--remote=pssl:0:127.0.0.1 \
db

while (true); do \
ovsdb-client \
--private-key=testpki-privkey.pem \
--certificate=testpki-cert.pem \
--ca-cert=testpki-cacert.pem \
dump ssl:127.0.0.1:42067; \
done

console2:
watch -n 0.5 'cat /proc/$(pidof ovsdb-server)/status | grep VmSize'

In console2 it was evidently seen ovsdb-server is constantly leaking memory. After a while
(i.e. after a certain number of reconnections) the OOM killer jumps out and kills ovsdb-server.

Very similar situation was already noticed and described in
openvswitch/ovs-issues#168. There, the problem pops up while connecting
controller to ovs-vswitchd daemon.

Valgrind reports point to a problem in openssl library, however after studying openssl code for
a while I have found out the problem is actually in ovs. When connection through SSL channel is
taken place openssl library allocates memory for keeping track of certificate. Reference to this
memory works very similar as std::shared_ptr pointer in recent C++ dialects. i.e. when allocated
memory is referenced its reference counter is incremented and decremented after the memory is
derefered. When reference counter becomes zero allocated memory is automatically deallocated.

In openssl library environment certificate is retrieved by calling SSL_get_peer_certificate()
where its reference counter is incremented. After retrieved certificate is not used any more its
reference counter must be decremented by calling X509_free(). If not, allocated memory is never
freed despite the ssl connection is properly closed.

The problem was caused in stream-ssl.c in function ssl_connect(), which retrieves common peer name
by calling SSL_get_peer_certificate() function and without calling X509_free() function afterwards.

Signed-off-by: Damijan Skvarc <damjan.skvarc@gmail.com>
Signed-off-by: Ben Pfaff <blp@ovn.org>
@yousong
Copy link

yousong commented Dec 25, 2020

We just upgraded from openvswitch 2.10.4 to 2.10.5 for 5 hosts. Three have a RSS about 1g in top command output, one 50g and another about 10g.

The host is running ovn-controller managing a integration bridge. There is also another our own build of agent managing 2 bridges with ovs-vsctl and ovs-ofctl. Number of flows are in the lower thousands, about 2000-4000.

I tried gcore and some simple chap commands. Here are some findings on rss 1g case

chap> count allocations
90944 allocations use 0x2b237078 (723,742,840) bytes.
chap> count used
86192 allocations use 0x29b0ff88 (699,465,608) bytes.
chap> count free
4752 allocations use 0x17270f0 (24,277,232) bytes.
chap> summarize used
Unrecognized allocations have 85919 instances taking 0x29ab8550(699,106,640) bytes.
   Unrecognized allocations of size 0x2668 have 70837 instances taking 0x29834788(696,469,384) bytes.
   Unrecognized allocations of size 0x28 have 3978 instances taking 0x26d90(159,120) bytes.
   Unrecognized allocations of size 0x18 have 3901 instances taking 0x16db8(93,624) bytes.
   Unrecognized allocations of size 0x188 have 1571 instances taking 0x96598(615,832) bytes.
   Unrecognized allocations of size 0x58 have 1212 instances taking 0x1a0a0(106,656) bytes.
   Unrecognized allocations of size 0x88 have 788 instances taking 0x1a2a0(107,168) bytes.
   Unrecognized allocations of size 0x38 have 738 instances taking 0xa170(41,328) bytes.
   Unrecognized allocations of size 0x48 have 698 instances taking 0xc450(50,256) bytes.
   Unrecognized allocations of size 0x68 have 562 instances taking 0xe450(58,448) bytes.
...

show used /size 0x2668 has the following dump for one of the allocate

Used allocation at 5600134c4180 of size 2668
   0:                0     560012fbd6a0              117                0
  20:                0                1     560013065be0                0
  40:                0                0                0     560012fbd6a0
  60:              118                0                0                1
  80:     5600130168a0                0                0                0
  a0:                0     560012fbd6a0              120                0
  c0:                0                1     560012f6b960                0
  e0:                0                0                0     560012fbd6a0
 100:              121                0                0                1
 120:     560012fe1910                0                0                0
 140:                0     560012fbd6a0              122                0
 160:                0                1     560013008730                0
 180:                0                0                0     560012fbd6a0
 1a0:              128                0                0                1
 1c0:     560013033330                0                0                0
 1e0:                0     560012fbd6a0              129                0
 200:                0                1     560013063c20                0
 220:                0                0                0     560012fbd6a0
 240:              12a                0                0                1
 260:     5600130899e0                0                0                0
 280:                0     560012fbd6a0              12b                0
 2a0:                0                1     560013042e10                0
 2c0:                0                0                0     560012fbd6a0
 2e0:              12c                0                0                1

And summarize incoming and outging

chap> summarize outgoing 0x5600134c4180
Unrecognized allocations have 116 instances taking 0xbb30(47,920) bytes.
   Unrecognized allocations of size 0x188 have 111 instances taking 0xa9f8(43,512) bytes.
   Unrecognized allocations of size 0x268 have 2 instances taking 0x4d0(1,232) bytes.
   Unrecognized allocations of size 0x568 have 2 instances taking 0xad0(2,768) bytes.
   Unrecognized allocations of size 0x198 have 1 instances taking 0x198(408) bytes.
116 allocations use 0xbb30 (47,920) bytes.
chap> summarize in
inaccessible  incoming
chap> summarize incoming 0x5600134c4180
0 allocations use 0x0 (0) bytes.

0x2668 is 9832 in decimal. pahole on ovs-vswitchd binary indicates that the closest match is ovsthread_key_slots struct of 8208 bytes

623 /* Per-thread data structure. */
624 struct ovsthread_key_slots {
625     struct ovs_list list_node;  /* In 'slots_list'. */
626     void **p1[L1_SIZE];
627 };

@yousong
Copy link

yousong commented Dec 26, 2020

Likely not ovsthread_key_slots. I checked with gdb, there were only 42 threads and slots_list is of length 41 excluding the head. Also the p1 member should be filled continuously

@yousong
Copy link

yousong commented Dec 28, 2020

0x560012fbd6a0 should be struct ofproto_dpif *. The size (1384) matches, and gdb data inspection also got sane result

(gdb) set $dpif = *(struct ofproto_dpif *)0x0000560012fbd6a0
(gdb) x/s (*(struct sset_node *)$dpif.ports.map.buckets[1]).name
0x56001305e070: "md-2a307921-c-p"
(gdb) x/s (*(struct sset_node *)$dpif.ports.map.buckets[2]).name
0x560013b3cb80: "vpc0n1-251"
(gdb) x/s (*(struct sset_node *)$dpif.ports.map.buckets[3]).name
0x560012fd94c0: "brvpc"

brvpc is the ovn integration bridge

summ  summarize incoming 0x0000560012fbd6a0
Unrecognized allocations have 72502 instances taking 0x298d4f90(697,126,800) bytes.
   Unrecognized allocations of size 0x2668 have 70837 instances taking 0x29834788(696,469,384) bytes.
   Unrecognized allocations of size 0x188 have 1548 instances taking 0x94260(606,816) bytes.
   Unrecognized allocations of size 0x198 have 51 instances taking 0x5148(20,808) bytes.
   Unrecognized allocations of size 0x248 have 39 instances taking 0x58f8(22,776) bytes.
   Unrecognized allocations of size 0x148 have 8 instances taking 0xa40(2,624) bytes.
   Unrecognized allocations of size 0x78 have 5 instances taking 0x258(600) bytes.
   Unrecognized allocations of size 0x88 have 5 instances taking 0x2a8(680) bytes.
   Unrecognized allocations of size 0x28 have 3 instances taking 0x78(120) bytes.
   Unrecognized allocations of size 0x58 have 1 instances taking 0x58(88) bytes.
   Unrecognized allocations of size 0xb8 have 1 instances taking 0xb8(184) bytes.
   Unrecognized allocations of size 0xe8 have 1 instances taking 0xe8(232) bytes.
   Unrecognized allocations of size 0x158 have 1 instances taking 0x158(344) bytes.
   Unrecognized allocations of size 0x258 have 1 instances taking 0x258(600) bytes.
   Unrecognized allocations of size 0x608 have 1 instances taking 0x608(1,544) bytes.
chap> describe allocation 0x0000560012fbd6a0
Anchored allocation at 560012fbd6a0 of size 568

1 allocations use 0x568 (1,384) bytes.

@yousong
Copy link

yousong commented Dec 28, 2020

Now I am fairly sure 0x5600134c4180 is content of struct xlate_cache. The question remains as why there are so many and each have the same size.

@casasfernando
Copy link
Author

casasfernando commented Dec 28, 2020

@yousong I still have the dump from last year in case you want to analyze it and compare it to what you see in yours. At least to understand if it can be the same issue or not.
Just let me know if you are interested.

Thanks

@yousong
Copy link

yousong commented Dec 28, 2020

Yes, I should have shared my coredump earlier. The xz-ed content is actually very small, only 2.2MB, vs. 3.6GB when decompressed. That's really unexpected.

Below is the link, with rpm and debuginfo.

https://drive.google.com/drive/folders/1Sr_fd6XitQISdy7gVLhlpdmYS6MWQg5J

@casasfernando
Copy link
Author

casasfernando commented Dec 28, 2020

Yes, I should have shared my coredump earlier. The xz-ed content is actually very small, only 2.2MB, vs. 3.6GB when decompressed. That's really unexpected.

Below is the link, with rpm and debuginfo.

https://drive.google.com/drive/folders/1Sr_fd6XitQISdy7gVLhlpdmYS6MWQg5J

Thanks for sharing the dump but probably I didn’t explain myself correctly.
I don’t have the skills to do the analysis you did on your dump so I was offering you mine in case you want to have a look at it and see if it has anything in common with yours that can help to narrow down the problem.

@yousong
Copy link

yousong commented Dec 29, 2020

Yes, I should have shared my coredump earlier. The xz-ed content is actually very small, only 2.2MB, vs. 3.6GB when decompressed. That's really unexpected.
Below is the link, with rpm and debuginfo.
https://drive.google.com/drive/folders/1Sr_fd6XitQISdy7gVLhlpdmYS6MWQg5J

Thanks for sharing the dump but probably I didn’t explain myself correctly.
I don’t have the skills to do the analysis you did on your dump so I was offering you mine in case you want to have a look at it and see if it has anything in common with yours that can help to narrow down the problem.

Yes, please do. My guess is that it would it take me a while checking with the code and tracking down the actual cause. It will boost the process if other devs more familiar with the codebase got a chance to try.

@yousong
Copy link

yousong commented Dec 29, 2020

The patch below should fix my issue with 2.10. Only after blaming master branch I realized that it was already fixed there with commit openvswitch/ovs@584992d . The upstream fix was only included in 2.13 and 2.14. So likely it should also help your case with 2.12

From 6e56458229d81aa48cc0c7e2f4d03af23733f0ba Mon Sep 17 00:00:00 2001
From: Yousong Zhou <yszhou4tech@gmail.com>
Date: Tue, 29 Dec 2020 12:04:27 +0800
Subject: [PATCH] ofproto-dpif: fix xcache mem leak in nxt_resume

Fixes: 72700fe0 ("ofproto-dpif: Fix NXT_RESUME flow stats")
Signed-off-by: Yousong Zhou <yszhou4tech@gmail.com>
---
 ofproto/ofproto-dpif.c | 1 +
 1 file changed, 1 insertion(+)

diff --git a/ofproto/ofproto-dpif.c b/ofproto/ofproto-dpif.c
index 6ad7b85fc..51fd0f463 100644
--- a/ofproto/ofproto-dpif.c
+++ b/ofproto/ofproto-dpif.c
@@ -5117,6 +5117,7 @@ nxt_resume(struct ofproto *ofproto_,
     /* Clean up. */
     ofpbuf_uninit(&odp_actions);
     dp_packet_uninit(&packet);
+    xlate_cache_uninit(&xcache);
 
     return error;
 }

@igsilya
Copy link
Member

igsilya commented Dec 29, 2020

Thanks, @yousong for your analysis!

The issue that fixed by commit openvswitch/ovs@584992d was introduced by a different bugfix commit openvswitch/ovs@2f355bf that got accepted to master in 2.11 release time frame. This buggy fix was backported to 2.10 and down to 2.8. So, it was released as part of 2.10.1 release. This matches with the description of this bug report giving at least some confidence that this is the root cause of the issue.
Memory leak, IIUC, was detected by valgrind during the blanket testing and the fix (commit openvswitch/ovs@584992d) was only backported down to 2.12 and is part of a 2.12.2 release.

I think we need to revisit the patch set https://patchwork.ozlabs.org/project/openvswitch/list/?series=130294&state=* and backport these fixes down to branches where issues were introduced. I will try to find some time for this somewhere next week.

Branches 2.11 and below will reach their EOL with release of 2.15, but they will have at least one more stable release before that.

@igsilya
Copy link
Member

igsilya commented Jan 14, 2021

I backported commit openvswitch/ovs@584992d to branches 2.8-2.11. Released as part of v2.11.5, v2.10.6, v2.9.8, and v2.8.10.

@casasfernando
Copy link
Author

casasfernando commented Jan 30, 2021

Today I upgraded to Alpine 3.13.1 which provides ovs v2.12.2.
I will monitor the memory usage for a few days and report back.

Thanks

@casasfernando
Copy link
Author

casasfernando commented Feb 2, 2021

Two and a half days in running v2.12.2 and the memory usage is stable at 12MB.
It looks very promising. I will monitor until Friday and if all goes well I close this issue.

Thanks

@igsilya
Copy link
Member

igsilya commented Feb 2, 2021

Thanks, @casasfernando, for the update. Sounds good so far.

@casasfernando
Copy link
Author

casasfernando commented Feb 5, 2021

After upgrading to v2.12.2 and monitoring memory usage for a week the problem is to be gone and I'm closing the issue.
Thanks everyone for your help on this issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

7 participants