File descriptor leak in haproxy with openssl plugin

[grzegorz2]

Hello

I'm using Plug&Trust version 4.01.01. accessManager is configured to using unix socket and my sss_engine uses accessManager to talk to the SE050 (build with option "-DPTMW_SMCOM=JRCP_V1_AM")

SE050 is using to store private key. This private key is using by haproxy to provide https server. Everything works fine until I want to reload haproxy configuration. When I use haproxy "master CLI" to reload with following command:

echo 'reload' | socat /var/run/haproxy.master -

I can see with "lsof" that haproxy has two more socket file descriptors and accessManager has one more additional opened socket. This sockets number increases with each haproxy reload (additional 2 sockets opened by haproxy and one opened by accessManager). In my system I can reach an opened file descriptors limit and block whole haproxy because of that. This sockets are cleared only if I stop haproxy service (number of opened file descriptors by the accessManager decreased rapidly).

May it be some issue in sss engine (it looks like something is not cleared properly when haproxy worker process is restarted) or is it configuration issue?

Regards

[Kan_Li]

Hi @grzegorz2 ,

Would you please specify the platform working with SE050? and is it possible to have the building configuration of MW? You may have it with "cmake -L ." at the build folder such as "simw-top_build".

and it would be better if you share a snapshot of the result out of "lsof" in that case.

Thanks for your patience!

Have a great day,
Kan

-------------------------------------------------------------------------------
Note:
- If this post answers your question, please click the "Mark Correct" button. Thank you!
- We are following threads for 7 weeks after the last post, later replies are ignored
Please open a new thread and refer to the closed one, if you have a related question at a later point in time.
-------------------------------------------------------------------------------

[grzegorz2]

Hi @Kan_Li 

I run build two times. One time to build "accessManager" binary and the second time to build "libsss_engine.so"
Build for "accessManage" was done by running cmake with these flags:

-DWithAccessMgr_UnixSocket:BOOL=ON \
-DPTMW_Host=Raspbian \
-DPTMW_Applet=SE05X_A \
-DCMAKE_BUILD_TYPE=Release \
-DCMAKE_TOOLCHAIN_FILE=../scripts/armgcc_force_cpp.cmake \
-DPTMW_HostCrypto=OPENSSL
-DPTMW_SE05X_Auth=PlatfSCP03 \
-DPTMW_SCP=SCP03_SSS \
-DPTMW_SMCOM=T1oI2C

cmake for build "libsss_engine.so" was run with these flags:

-DWithAccessMgr_UnixSocket:BOOL=ON \
-DPTMW_Host=Raspbian \
-DPTMW_Applet=SE05X_A \
-DCMAKE_BUILD_TYPE=Release \
-DCMAKE_TOOLCHAIN_FILE=../scripts/armgcc_force_cpp.cmake \
-DPTMW_HostCrypto=OPENSSL
-DPTMW_SE05X_Auth=None \
-DPTMW_SCP=None \
-DPTMW_SMCOM=JRCP_V1_AM

System is not a Raspbian. This is a Linux running on ARM processor Ambarella CV25_m

There is a lot of entries by running "lsof" so maybe I will filter it out:

Before haproxy refresh:

# lsof | grep -E "haproxy.*socket"
435 /usr/local/bin/haproxy socket:[4044]
435 /usr/local/bin/haproxy socket:[716]
435 /usr/local/bin/haproxy socket:[907]
435 /usr/local/bin/haproxy socket:[915]
435 /usr/local/bin/haproxy socket:[929]
527 /usr/local/bin/haproxy socket:[4044]
527 /usr/local/bin/haproxy socket:[716]
527 /usr/local/bin/haproxy socket:[907]
527 /usr/local/bin/haproxy socket:[916]
527 /usr/local/bin/haproxy socket:[923]
527 /usr/local/bin/haproxy socket:[728]
527 /usr/local/bin/haproxy socket:[729]
527 /usr/local/bin/haproxy socket:[925]
527 /usr/local/bin/haproxy socket:[927]
527 /usr/local/bin/haproxy socket:[9808]
527 /usr/local/bin/haproxy socket:[9806]
527 /usr/local/bin/haproxy socket:[9082]
527 /usr/local/bin/haproxy socket:[9977]
527 /usr/local/bin/haproxy socket:[9790]
527 /usr/local/bin/haproxy socket:[4347]
527 /usr/local/bin/haproxy socket:[9851]
527 /usr/local/bin/haproxy socket:[4349]
527 /usr/local/bin/haproxy socket:[9859]
527 /usr/local/bin/haproxy socket:[9860]
527 /usr/local/bin/haproxy socket:[9862]
527 /usr/local/bin/haproxy socket:[9863]
527 /usr/local/bin/haproxy socket:[9865]
527 /usr/local/bin/haproxy socket:[9866]
527 /usr/local/bin/haproxy socket:[9096]
527 /usr/local/bin/haproxy socket:[9097]
527 /usr/local/bin/haproxy socket:[9099]
527 /usr/local/bin/haproxy socket:[9100]
527 /usr/local/bin/haproxy socket:[4351]
527 /usr/local/bin/haproxy socket:[9102]
527 /usr/local/bin/haproxy socket:[9886]
527 /usr/local/bin/haproxy socket:[9889]
527 /usr/local/bin/haproxy socket:[9890]
527 /usr/local/bin/haproxy socket:[9891]
# lsof | grep -E "haproxy.*socket" | wc -l
38

38 sockets opened by haproxy

# lsof | grep -E "accessManager.*socket"
191 /usr/local/bin/accessManager socket:[3271]
191 /usr/local/bin/accessManager socket:[3777]
191 /usr/local/bin/accessManager socket:[3779]
191 /usr/local/bin/accessManager socket:[3782]
191 /usr/local/bin/accessManager socket:[3845]
191 /usr/local/bin/accessManager socket:[4045]
191 /usr/local/bin/accessManager socket:[4076]
# lsof | grep -E "accessManager.*socket" | wc -l
7

7 sockets opened by accessManager

After first haproxy refresh:
# lsof | grep -E "haproxy.*socket"
435 /usr/local/bin/haproxy socket:[73781]
435 /usr/local/bin/haproxy socket:[716]
435 /usr/local/bin/haproxy socket:[73782]
435 /usr/local/bin/haproxy socket:[907]
435 /usr/local/bin/haproxy socket:[915]
435 /usr/local/bin/haproxy socket:[72794]
435 /usr/local/bin/haproxy socket:[72807]
527 /usr/local/bin/haproxy socket:[4044]
527 /usr/local/bin/haproxy socket:[716]
527 /usr/local/bin/haproxy socket:[907]
527 /usr/local/bin/haproxy socket:[916]
527 /usr/local/bin/haproxy socket:[9859]
527 /usr/local/bin/haproxy socket:[9860]
527 /usr/local/bin/haproxy socket:[9862]
527 /usr/local/bin/haproxy socket:[9863]
527 /usr/local/bin/haproxy socket:[9865]
527 /usr/local/bin/haproxy socket:[9866]
527 /usr/local/bin/haproxy socket:[9096]
527 /usr/local/bin/haproxy socket:[9097]
527 /usr/local/bin/haproxy socket:[9099]
527 /usr/local/bin/haproxy socket:[9100]
527 /usr/local/bin/haproxy socket:[4351]
527 /usr/local/bin/haproxy socket:[9102]
527 /usr/local/bin/haproxy socket:[9886]
527 /usr/local/bin/haproxy socket:[9889]
527 /usr/local/bin/haproxy socket:[9890]
527 /usr/local/bin/haproxy socket:[9891]
1327 /usr/local/bin/haproxy socket:[73781]
1327 /usr/local/bin/haproxy socket:[716]
1327 /usr/local/bin/haproxy socket:[73782]
1327 /usr/local/bin/haproxy socket:[907]
1327 /usr/local/bin/haproxy socket:[72795]
1327 /usr/local/bin/haproxy socket:[72801]
1327 /usr/local/bin/haproxy socket:[728]
1327 /usr/local/bin/haproxy socket:[729]
1327 /usr/local/bin/haproxy socket:[72803]
1327 /usr/local/bin/haproxy socket:[72805]
1327 /usr/local/bin/haproxy socket:[72830]
1327 /usr/local/bin/haproxy socket:[72832]
1327 /usr/local/bin/haproxy socket:[72833]
1327 /usr/local/bin/haproxy socket:[72835]
# lsof | grep -E "haproxy.*socket" | wc -l
41

# lsof | grep -E "accessManager.*socket"
191 /usr/local/bin/accessManager socket:[3271]
191 /usr/local/bin/accessManager socket:[3777]
191 /usr/local/bin/accessManager socket:[3779]
191 /usr/local/bin/accessManager socket:[3782]
191 /usr/local/bin/accessManager socket:[3845]
191 /usr/local/bin/accessManager socket:[4045]
191 /usr/local/bin/accessManager socket:[4076]
191 /usr/local/bin/accessManager socket:[72789]
# lsof | grep -E "accessManager.*socket" | wc -l
8

after next refresh:
# lsof | grep -E "haproxy.*socket" | wc -l
43
# lsof | grep -E "accessManager.*socket" | wc -l
9

when I run refresh additionally 10 times:
# lsof | grep -E "haproxy.*socket" | wc -l
63
# lsof | grep -E "accessManager.*socket" | wc -l
19

These sockets number constantly increases when I'm refreshing configuration of haproxy. When I shutdown haproxy then accessManager closes it sockets

# echo "d" > /var/service/haproxy/supervise/control
# lsof | grep -E "accessManager.*socket" | wc -l
5

These remaining 5 sockets are opened because of another applications.

TLS connections works fine until haproxy reaches opened file descriptors limit.

In the tests above there weren't any TLS connections established by external TLS clients to haproxy. Actually haproxy did nothing but refreshing configuration.

Haproxy was started by this command:

/usr/local/bin/haproxy -f /tmp/haproxy_dynamic.conf -p /var/service/haproxy/pid -W -S /var/run/haproxy.master

and then I can use haproxy "master CLI", to refresh configuration I run:

echo 'reload' | socat /var/run/haproxy.master -

[Kan_Li]

Hi @grzegorz2 ,

Thanks for the information! Would you please specify the procedure of starting the accessManager and haproxy? did you start the accessManager in one console and haproxy in another such as below?

Please kindly clarify. You may refer to "simw-top/doc/hostlib/hostLib/accessManager/doc/accessManager.html" for more details.

Have a great day,
Kan

-------------------------------------------------------------------------------
Note:
- If this post answers your question, please click the "Mark Correct" button. Thank you!
- We are following threads for 7 weeks after the last post, later replies are ignored
Please open a new thread and refer to the closed one, if you have a related question at a later point in time.
-------------------------------------------------------------------------------

[grzegorz2]

Hi @Kan_Li 

Could we expect official patch for this?

Regards

[Kan_Li]

Hi @grzegorz2 ,

I just got the feedback from the expert, and he can replicate this issue and reported it to R&D side, but so far we are not absolutely sure if we don't get side effects here though your solution looks good to me and seems to make sense in general , but that really might depend on the expectation of the  individual application. 

Is this also happening on other situations or only on reload?

Have a great day,
Kan

-------------------------------------------------------------------------------
Note:
- If this post answers your question, please click the "Mark Correct" button. Thank you!
- We are following threads for 7 weeks after the last post, later replies are ignored
Please open a new thread and refer to the closed one, if you have a related question at a later point in time.
-------------------------------------------------------------------------------

[grzegorz2]

Hi @Kan_Li 

We see this issue only on "reload" command sent to haproxy but I'm pretty sure that it will be reproduced on every application that forks its main process (call "fork" and "execv", "popen", "system" etc.)

For now we are using modified version of this fix. "fcntl" is not used but we added "SOCK_CLOEXEC" during socket creation

pSockCtx->sockfd = socket(AF_UNIX, SOCK_STREAM | SOCK_CLOEXEC, 0);

This is because of race condition which would happen during call to "fork" but before call to "fcntl" and after call to "socket" by another thread.

Regards

[Kan_Li]

Hi @grzegorz2 ,

Thanks for the information! I have forwarded to our expert team and will let you know if there is any feedback from there.

Have a great day,
Kan

-------------------------------------------------------------------------------
Note:
- If this post answers your question, please click the "Mark Correct" button. Thank you!
- We are following threads for 7 weeks after the last post, later replies are ignored
Please open a new thread and refer to the closed one, if you have a related question at a later point in time.
-------------------------------------------------------------------------------

[Kan_Li]

Hi @grzegorz2 ,

Thanks for the information! 

I am checking with the expert regarding this issue, and will let you know when I have any feedback from there.

Thanks for your patience!

Have a great day,
Kan

-------------------------------------------------------------------------------
Note:
- If this post answers your question, please click the "Mark Correct" button. Thank you!
- We are following threads for 7 weeks after the last post, later replies are ignored
Please open a new thread and refer to the closed one, if you have a related question at a later point in time.
-------------------------------------------------------------------------------

[grzegorz2]

Hi @Kan_Li 

I was looking at this sss engine code and I found a place where unix socket is created in

"simw-top/hostlib/hostLib/libCommon/smCom/smComSocket_linux.c"

in "smComSocket_Open" function

I added some logging and I see that this "pSockCtx->sockfd" is open each time I reload haproxy but there is also called function "smComSocket_Close" which probably closes previous socket so it looks ok but I did some modification during socket creation after this line:

pSockCtx->sockfd = socket(AF_UNIX, SOCK_STREAM, 0);

I set flag "FD_CLOEXEC" to this socket by adding this code below:

if (fcntl(pSockCtx->sockfd, F_SETFD, FD_CLOEXEC) == -1) {
printf("fcntl failed\n");
}

With this modification issue is not reproducible. I can't see any leaked sockets after haproxy refresh. This flag causes linux kernel to close this file descriptor automatically when application calls "execv". Probably all file descriptors that this library using internally will be leaked when application will call "fork" and "execv" (this is how haproxy reloads configuration, it kills its child process and creates a new one).

I'm not sure if I don't break some other feature with this modification because I'm not familiar with this code and logic.

Regards

[grzegorz2]

Hi @Kan_Li 

I started both applications as linux service and both running in the background. I can also start them in a separate consoles and issue still occurs. I can't see any errors in the output logs, for example:

First console

# EX_SSS_BOOT_SCP03_PATH=/root/config/dynamic/scp_keys /usr/local/bin/accessManager
Using /dev/i2c-1
Starting accessManager (Rev.1.1).
Protect Link between accessManager and SE: YES.
accessManager JRCPv1 (T1oI2C SE side)
******************************************************************************
Server: waiting for connections.
New client connection. Client ID: 4
Command 0x00 from client 4
DUMMY_ATR=0x00.A0.00.00.03.96.04.03.E8.00.FE.02.0B.03.E8.08.01.00.00.00.00.64.00.00.0A.4A.43.4F.50.34.20.41.54.50.4F.
Replacing *_ATR by default (pre-cooked) ATR.
ATR=0x3B.FB.18.00.00.81.31.FE.45.50.4C.41.43.45.48.4F.4C.44.45.52.AB.
Command 0x01 from client 4
SM_EstablishPlatformSCP03Am (Entry)
App :WARN :Using SCP03 keys from:'/root/config/dynamic/scp_keys' (ENV=EX_SSS_BOOT_SCP03_PATH)
SE050 connected.
SM_EstablishPlatformSCP03Am (Exit); Status = 0x9000
Command 0x01 from client 4
SM_SendAPDUAm: smStatus = 0x9000
Command 0x01 from client 4
SM_SendAPDUAm: smStatus = 0x9000

Second console

# /usr/local/bin/haproxy -f /tmp/haproxy_dynamic.conf -p /var/service/haproxy/pid -W -S /var/run/haproxy.master
ssse-flw: EmbSe_Init(): Entry
App :INFO :Using PortName='/var/run/am' (gszSocketPortDefault)
App :INFO :If you want to over-ride the selection, use ENV=EX_SSS_BOOT_SSS_PORT or pass in command line arguments.
sss :INFO :Newer version of Applet Found
sss :INFO :Compiled for 0x30100. Got newer 0x30600
sss :WARN :Communication channel is Plain.
sss :WARN :!!!Not recommended for production use.!!!
ssse-flw: Version: 1.0.5
ssse-flw: EmbSe_Init(): Exit
[WARNING] 082/061321 (3348) : parsing [/tmp/haproxy_dynamic.conf:51] : a 'http-request' rule placed after a 'use_backend' rule will still be processed before.
[WARNING] 082/061321 (3348) : parsing [/tmp/haproxy_dynamic.conf:66] : a 'tcp-request' rule placed after an 'http-request' rule will still be processed before.
[WARNING] 082/061321 (3348) : parsing [/tmp/haproxy_dynamic.conf:100] : a 'http-request' rule placed after a 'use_backend' rule will still be processed before.
[WARNING] 082/061321 (3348) : parsing [/tmp/haproxy_dynamic.conf:137] : a 'http-request' rule placed after a 'use_backend' rule will still be processed before.
[WARNING] 082/061321 (3348) : config : 'http-request' rules ignored for frontend 'tcpt' as they require HTTP mode.
[WARNING] 082/061321 (3348) : config : 'http-response' rules ignored for frontend 'tcpt' as they require HTTP mode.
[NOTICE] 082/061321 (3348) : New worker #1 (3350) forked
ssse-dbg: Using keyId=0x0000000B
ssse-dbg: shaAlgo: 773
ssse-flw: SSS based sign (keyId=0x0000000B, dgstLen=64)
ssse-dbg: Using keyId=0x0000000B
ssse-dbg: shaAlgo: 773
ssse-flw: SSS based sign (keyId=0x0000000B, dgstLen=64)
ssse-dbg: Using keyId=0x0000000B
ssse-dbg: shaAlgo: 773
ssse-flw: SSS based sign (keyId=0x0000000B, dgstLen=64)
ssse-flw: SSS based sign called successfully (sigDERLen=104)
ssse-flw: EmbSe_ECDSA_Do_Sign success.
ssse-flw: EmbSe_Simple_Compute_Key invoked (ecdh)
ssse-dbg: ** nid = 715 **
ssse-flw: No matching key in SE. Invoking OpenSSL API: ECDH_compute_key.
ssse-flw: ECDH_compute_key by OpenSSL PASS
ssse-flw: SSS based sign called successfully (sigDERLen=103)
ssse-flw: EmbSe_ECDSA_Do_Sign success.
ssse-flw: EmbSe_Simple_Compute_Key invoked (ecdh)
ssse-dbg: ** nid = 715 **
ssse-flw: No matching key in SE. Invoking OpenSSL API: ECDH_compute_key.
ssse-dbg: Using keyId=0x0000000B
ssse-dbg: shaAlgo: 773
ssse-flw: SSS based sign (keyId=0x0000000B, dgstLen=64)
ssse-flw: ECDH_compute_key by OpenSSL PASS
ssse-flw: SSS based sign called successfully (sigDERLen=103)
ssse-flw: EmbSe_ECDSA_Do_Sign success.
ssse-flw: EmbSe_Simple_Compute_Key invoked (ecdh)
ssse-dbg: ** nid = 715 **
ssse-flw: No matching key in SE. Invoking OpenSSL API: ECDH_compute_key.
ssse-flw: ECDH_compute_key by OpenSSL PASS
ssse-flw: SSS based sign called successfully (sigDERLen=102)
ssse-flw: EmbSe_ECDSA_Do_Sign success.
ssse-flw: EmbSe_Simple_Compute_Key invoked (ecdh)
ssse-dbg: ** nid = 715 **
ssse-flw: No matching key in SE. Invoking OpenSSL API: ECDH_compute_key.
ssse-flw: ECDH_compute_key by OpenSSL PASS
ssse-dbg: Using keyId=0x0000000B
ssse-dbg: shaAlgo: 773
ssse-flw: SSS based sign (keyId=0x0000000B, dgstLen=64)
ssse-flw: SSS based sign called successfully (sigDERLen=102)
ssse-flw: EmbSe_ECDSA_Do_Sign success.
ssse-flw: EmbSe_Simple_Compute_Key invoked (ecdh)
ssse-dbg: ** nid = 715 **
ssse-flw: No matching key in SE. Invoking OpenSSL API: ECDH_compute_key.
ssse-flw: ECDH_compute_key by OpenSSL PASS

after haproxy refresh

[WARNING] 082/061407 (3348) : Reexecuting Master process
ssse-flw: EmbSe_Init(): Entry
App :INFO :Using PortName='/var/run/am' (gszSocketPortDefault)
App :INFO :If you want to over-ride the selection, use ENV=EX_SSS_BOOT_SSS_PORT or pass in command line arguments.
sss :INFO :Newer version of Applet Found
sss :INFO :Compiled for 0x30100. Got newer 0x30600
sss :WARN :Communication channel is Plain.
sss :WARN :!!!Not recommended for production use.!!!
ssse-flw: Version: 1.0.5
ssse-flw: EmbSe_Init(): Exit
[WARNING] 082/061408 (3348) : parsing [/tmp/haproxy_dynamic.conf:51] : a 'http-request' rule placed after a 'use_backend' rule will still be processed before.
[WARNING] 082/061408 (3348) : parsing [/tmp/haproxy_dynamic.conf:66] : a 'tcp-request' rule placed after an 'http-request' rule will still be processed before.
[WARNING] 082/061408 (3348) : parsing [/tmp/haproxy_dynamic.conf:100] : a 'http-request' rule placed after a 'use_backend' rule will still be processed before.
[WARNING] 082/061408 (3348) : parsing [/tmp/haproxy_dynamic.conf:137] : a 'http-request' rule placed after a 'use_backend' rule will still be processed before.
[WARNING] 082/061408 (3348) : config : 'http-request' rules ignored for frontend 'tcpt' as they require HTTP mode.
[WARNING] 082/061408 (3348) : config : 'http-response' rules ignored for frontend 'tcpt' as they require HTTP mode.
[WARNING] 082/061408 (3350) : Proxy http-80 stopped (cumulated conns: FE: 0, BE: 0).
[WARNING] 082/061408 (3350) : Proxy tcpt stopped (cumulated conns: FE: 5, BE: 0).
[WARNING] 082/061408 (3350) : Proxy tlsnew stopped (cumulated conns: FE: 29, BE: 0).
[WARNING] 082/061408 (3350) : Proxy tlsold stopped (cumulated conns: FE: 23, BE: 0).
[WARNING] 082/061408 (3350) : Stopping frontend GLOBAL in 0 ms.
[WARNING] 082/061408 (3350) : Stopping backend tcpnew in 0 ms.
[WARNING] 082/061408 (3350) : Stopping backend tcpold in 0 ms.
[WARNING] 082/061408 (3350) : Stopping backend cameraApp in 0 ms.
[WARNING] 082/061408 (3350) : Stopping backend storageApp in 0 ms.
[WARNING] 082/061408 (3350) : Stopping backend intercomApp in 0 ms.
[WARNING] 082/061408 (3350) : Stopping backend cameraAppUpgradePath in 0 ms.
[NOTICE] 082/061408 (3348) : New worker #1 (3431) forked

This is very easy to reproduce and I believe that this issue is connected to haproxy reload mechanism and I think you should be able to reproduce it on any linux system

Regards