Bug 1405910

Summary:	Need a way to reduce the logging of messages "Peer CN" and "SSL verification suceeded messages" in glusterd.log file
Product:	[Red Hat Storage] Red Hat Gluster Storage	Reporter:	RamaKasturi <knarra>
Component:	core	Assignee:	Mohit Agrawal <moagrawa>
Status:	CLOSED ERRATA	QA Contact:	Bala Konda Reddy M <bmekala>
Severity:	high	Docs Contact:
Priority:	unspecified
Version:	rhgs-3.2	CC:	amukherj, asoman, asrivast, moagrawa, rhinduja, rhs-bugs, sabose, sasundar, storage-qa-internal, vbellur
Target Milestone:	---
Target Release:	RHGS 3.3.0
Hardware:	x86_64
OS:	Linux
Whiteboard:	ssl
Fixed In Version:	glusterfs-3.8.4-19	Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:
Clones:	1427018 (view as bug list)		Environment:
Last Closed:	2017-09-21 04:30:55 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:
Bug Blocks:	1417147, 1427018

Description RamaKasturi 2016-12-19 06:52:38 UTC

Description of problem:
When SSL is enabled on management and I/O path i see that the following messages gets logged in glusterd.log every minute.
[2016-12-19 06:45:28.516570] I [socket.c:343:ssl_setup_connection] 0-socket.management: peer CN = 10.70.36.83
[2016-12-19 06:45:28.516595] I [socket.c:346:ssl_setup_connection] 0-socket.management: SSL verification succeeded (client: 10.70.36.83:993)
[2016-12-19 06:45:39.458207] I [socket.c:343:ssl_setup_connection] 0-socket.management: peer CN = 10.70.36.83
[2016-12-19 06:45:39.458237] I [socket.c:346:ssl_setup_connection] 0-socket.management: SSL verification succeeded (client: 10.70.36.83:993)
[2016-12-19 06:45:55.225697] I [socket.c:343:ssl_setup_connection] 0-socket.management: peer CN = 10.70.36.83
[2016-12-19 06:45:55.225734] I [socket.c:346:ssl_setup_connection] 0-socket.management: SSL verification succeeded (client: 10.70.36.83:992)
[2016-12-19 06:45:55.326944] I [MSGID: 106488] [glusterd-handler.c:1539:__glusterd_handle_cli_get_volume] 0-management: Received get vol req
[2016-12-19 06:45:55.426240] I [socket.c:343:ssl_setup_connection] 0-socket.management: peer CN = 10.70.36.82
[2016-12-19 06:45:55.426259] I [socket.c:346:ssl_setup_connection] 0-socket.management: SSL verification succeeded (client: 10.70.36.82:985)
[2016-12-19 06:46:01.541826] I [socket.c:343:ssl_setup_connection] 0-socket.management: peer CN = 10.70.36.83
[2016-12-19 06:46:01.541857] I [socket.c:346:ssl_setup_connection] 0-socket.management: SSL verification succeeded (client: 10.70.36.83:992)
[2016-12-19 06:46:03.414618] I [socket.c:343:ssl_setup_connection] 0-socket.management: peer CN = 10.70.36.82
[2016-12-19 06:46:03.414639] I [socket.c:346:ssl_setup_connection] 0-socket.management: SSL verification succeeded (client: 10.70.36.82:985)
[2016-12-19 06:46:08.844772] I [socket.c:343:ssl_setup_connection] 0-socket.management: peer CN = 10.70.36.83
[2016-12-19 06:46:08.844790] I [socket.c:346:ssl_setup_connection] 0-socket.management: SSL verification succeeded (client: 10.70.36.83:992)
[2016-12-19 06:46:11.416595] I [socket.c:343:ssl_setup_connection] 0-socket.management: peer CN = 10.70.36.83
[2016-12-19 06:46:11.416614] I [socket.c:346:ssl_setup_connection] 0-socket.management: SSL verification succeeded (client: 10.70.36.83:993)
[2016-12-19 06:46:14.766104] I [socket.c:343:ssl_setup_connection] 0-socket.management: peer CN = 10.70.36.83
[2016-12-19 06:46:14.766136] I [socket.c:346:ssl_setup_connection] 0-socket.management: SSL verification succeeded (client: 10.70.36.83:992)
[2016-12-19 06:46:39.404440] I [socket.c:343:ssl_setup_connection] 0-socket.management: peer CN = 10.70.36.84
[2016-12-19 06:46:39.404463] I [socket.c:346:ssl_setup_connection] 0-socket.management: SSL verification succeeded (client: 10.70.36.84:992)

There should be a way to reduce the logging of these messages in glusterd.log file

Version-Release number of selected component (if applicable):
glusterfs-3.8.4-8.el7rhgs.x86_64

How reproducible:
Always

Steps to Reproduce:
1. Have three nodes with glusterfs installed
2. Enable SSL on both management and I/O path.
3. After successful enablement look at glusterd.log file.

Actual results:
I see that the following messages comes in glusterd.log every minute.

[2016-12-19 06:49:55.434637] I [socket.c:343:ssl_setup_connection] 0-socket.management: peer CN = 10.70.36.83
[2016-12-19 06:49:55.434661] I [socket.c:346:ssl_setup_connection] 0-socket.management: SSL verification succeeded (client: 10.70.36.83:993)
[2016-12-19 06:50:00.382347] I [socket.c:343:ssl_setup_connection] 0-socket.management: peer CN = 10.70.36.82
[2016-12-19 06:50:00.382366] I [socket.c:346:ssl_setup_connection] 0-socket.management: SSL verification succeeded (client: 10.70.36.82:985)
[2016-12-19 06:50:02.368641] I [socket.c:343:ssl_setup_connection] 0-socket.management: peer CN = 10.70.36.82
[2016-12-19 06:50:02.368659] I [socket.c:346:ssl_setup_connection] 0-socket.management: SSL verification succeeded (client: 10.70.36.82:985)
[2016-12-19 06:50:03.378959] I [socket.c:343:ssl_setup_connection] 0-socket.management: peer CN = 10.70.36.82
[2016-12-19 06:50:03.378977] I [socket.c:346:ssl_setup_connection] 0-socket.management: SSL verification succeeded (client: 10.70.36.82:985)
[2016-12-19 06:50:11.385735] I [socket.c:343:ssl_setup_connection] 0-socket.management: peer CN = 10.70.36.83
[2016-12-19 06:50:11.385754] I [socket.c:346:ssl_setup_connection] 0-socket.management: SSL verification succeeded (client: 10.70.36.83:993)
[2016-12-19 06:50:39.418306] I [socket.c:343:ssl_setup_connection] 0-socket.management: peer CN = 10.70.36.83
[2016-12-19 06:50:39.418326] I [socket.c:346:ssl_setup_connection] 0-socket.management: SSL verification succeeded (client: 10.70.36.83:993)
[2016-12-19 06:50:55.415020] I [socket.c:343:ssl_setup_connection] 0-socket.management: peer CN = 10.70.36.82
[2016-12-19 06:50:55.415036] I [socket.c:346:ssl_setup_connection] 0-socket.management: SSL verification succeeded (client: 10.70.36.82:985)
[2016-12-19 06:51:03.364260] I [socket.c:343:ssl_setup_connection] 0-socket.management: peer CN = 10.70.36.82
[2016-12-19 06:51:03.364281] I [socket.c:346:ssl_setup_connection] 0-socket.management: SSL verification succeeded (client: 10.70.36.82:985)


Expected results:
There should be a way to reduce these messages in glusterd.log file.

Additional info:

Comment 4 Ambarish 2016-12-20 06:41:00 UTC

Reproduced this on my setup.
4 Nodes,4 clients,1:1 mount via FUSE.
Was running Bonnie++ default workload on all 4 mounts in different subdirectories.

I see the following message being logged almost every second :

[2016-12-20 06:12:55.755106] I [socket.c:343:ssl_setup_connection] 0-socket.management: peer CN = gqas010.sbu.lab.eng.bos.redhat.com
[2016-12-20 06:12:55.755136] I [socket.c:346:ssl_setup_connection] 0-socket.management: SSL verification succeeded (client: 192.168.79.141:1007)

The message has been logged almost 45000 times in 24 hours and my logsize has bloated to 12MB in 24 hours.This is concerning as the logging is a bit over-zealous and  is filling up "/" quickly.

Comment 6 Byreddy 2016-12-21 06:37:44 UTC

Similar issue bug - https://bugzilla.redhat.com/show_bug.cgi?id=1389678

Comment 7 Sahina Bose 2016-12-21 07:04:35 UTC

This would be an issue with Grafton on deployments with SSL enabled.

Comment 8 Byreddy 2016-12-21 08:39:02 UTC

Got a chance to check this issue, here is the update.

I am seeing this issue in my setup only when the FUSE mounted volume is stopped, this bz https://bugzilla.redhat.com/show_bug.cgi?id=1389678 tracks issue and  
not seeing this issue when the setup is idle OR busy with IOs

Comment 12 Mohit Agrawal 2017-02-27 05:56:12 UTC

Posted a patch for the same in upstream
https://review.gluster.org/#/c/16767/1

Comment 14 Atin Mukherjee 2017-03-24 09:58:50 UTC

downstream patch : https://code.engineering.redhat.com/gerrit/#/c/101323/

Comment 16 Bala Konda Reddy M 2017-07-25 08:50:04 UTC

BUILD : 3.8.4-35

Followed the steps mentioned in the bug, Not getting continuous info messages related to "Peer CN" and "SSL verification succeeded messages". 

Hence marking the bug as verified

Comment 18 errata-xmlrpc 2017-09-21 04:30:55 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2017:2774

Comment 19 errata-xmlrpc 2017-09-21 04:56:40 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2017:2774