MySQL Backup not possible because of Log4J usage

Hi @thomas.S

It's a false positive, we don't use Log4j for the MySQL agent.

Regards,
Vairavaprakash

Hi @thomas.S 

To my knowledge and according to the latest info here:
 

• Log4j Vulnerability - Please Post All Questions Here

MySQL agent isn’t affected by Log4J vulnerability CVE-2021-44228, so we’ll need some more details to figure out what is causing this alert you’re seeing.

Are you able to check the logs on the client or JobManager.log on the Commserve, usually a process will throw an error and allow us to narrow in on what is getting caught.

Thanks,

Stuart 

Hello @Stuart Painter, 

I have here an extract of the JobManager.log.
According to the extract there are problems with communication. The readyness check shows no problems and also the installation of the agent was possible without problems. Only when trying to create a backup it runs into this error.

6220  37e4  01/20 04:36:06 3867301 Scheduler  Set pending cause [A time-out has occurred while initializing data transfer with MediaAgent [cvmapapp02].  Please check the following
If this is a LAN Data Transfer, check network connectivity between the Client and MediaAgent.
For Network Free Data Transfer verify that there are no issues with the secondary storage device on the MediaAgent.]::Client [hovspmd2] Application [MySqlBackupChild] Message Id [218103893] RCID [0] ReservationId [0].  Level [0] flags [0] id [0] overwrite [0] append [0] CustId[0].
6220  4978  01/20 04:36:06 3867301 Servant    Remote free streams request received for rcid [7603387]
6220  494c  01/20 04:36:06 3867301 Scheduler  Phase [Failed] message received from [hovspmd2] Module [MySqlBackupParent] Token [3867301:7:4:1:51234] restartPhase [0]
6220  494c  01/20 04:36:06 3867301 Delay Msg  JMJobUpdateMsg table record saved [saveJMJobUpdateMsg]. status 2 statusFor 1 token<3867301:7:4:1:51234>
6220  2278  01/20 04:36:07 ####### Servant    Reservation lookup. Failure list:: jobid[3869011] requestid [16276493]
6220  2278  01/20 04:36:07 3869011 JobSvr Obj Resource allocation failed for this job. error code [20045] error string [Library [Norderstedt], MediaAgent [cvmapapp02], Drive Pool [DrivePool(cvmapapp02)10], Media[]: . Job had reserved a stream, but no remaining streams are available for the job anymore. Please check stream usage of current job and jobs running to this Storage Policy. Waiting streams of current job will run once more stream becomes available.

Hello @Vairavaprakash, 

I actually assumed that, but that doesn't explain why the communication is blocked.

 

Hi Thomas,

can you please open a TR with support team so we can take a look at this issue in zoom session?

Is this issue isolated one MySQL server?

Thanks,

Brahma

Hello @Brahma 

yes I will open a TR. I'm still waiting for a feedback, because I can't currently open tickets myself via the ma.commvault.com. This is being checked right now. We applied for premium support a few months ago. 

Yes, the issue only affects one MySQL server. 

with kind regards

Thomas

Hello, 

Log4J could now not be found on the affected system, yet the backup does not run. It performs a scan, then goes to Running but does not transfer any data. We have collected a few logs here. maybe someone here can say something about it. 

cvd.log 10963 5f36 01/27 20:19:29 ### [CVipcD] ERROR: slRecvMsgWithTout(): allocated buffer size (65536) is less than incoming packet size (1212501072) 10963 6a31 01/27 20:19:29 ### [CVipcD] ERROR: slRecvMsgWithTout(): allocated buffer size (65536) is less than incoming packet size (50331667) 10963 6e3f 01/27 20:19:29 ### [CVipcD] ERROR: slRecvMsgWithTout(): allocated buffer size (65536) is less than incoming packet size (50399744) 10963 5f36 01/27 20:19:29 ### [CVipcD] ERROR: slRecvMsgWithTout(): allocated buffer size (65536) is less than incoming packet size (369295618) 10963 6a31 01/27 20:19:30 ### [CVipcD] ERROR: slRecvMsgWithTout(): allocated buffer size (65536) is less than incoming packet size (1195725856) 10963 6e3f 01/27 20:19:30 ### [CVipcD] ERROR: slRecvMsgWithTout(): allocated buffer size (65536) is less than incoming packet size (1195725856) 10963 6e3f 01/27 20:19:30 ### [CVipcD] ERROR: slRecvMsgWithTout(): allocated buffer size (65536) is less than incoming packet size (1195725856) 10963 6a31 01/27 20:19:30 ### [CVipcD] ERROR: slRecvMsgWithTout(): allocated buffer size (65536) is less than incoming packet size (369295618) 10963 6a31 01/27 20:19:30 ### [CVipcD] ERROR: slRecvMsgWithTout(): allocated buffer size (65536) is less than incoming packet size (1195725856)

10965 2ad5 01/27 20:19:07 TN:00032 ######## ERROR: cvfwd_dispatch_one_tunnel(): Received invalid command from fd=12. Drop the socket. 10965 2ad5 01/27 20:19:10 TN:00033 ######## ERROR: cvfwd_dispatch_one_tunnel(): Received invalid command from fd=12. Drop the socket. 10965 2ad5 01/27 20:19:10 TN:00034 ######## ERROR: cvfwd_dispatch_one_tunnel(): Received invalid command from fd=12. Drop the socket. 10965 2ad5 01/27 20:19:10 TN:00035 ######## ERROR: cvfwd_dispatch_one_tunnel(): Received invalid command from fd=12. Drop the socket. 10965 2ad5 01/27 20:19:12 TN:00036 ######## ERROR: cvfwd_dispatch_one_tunnel(): Received invalid command from fd=12. Drop the socket. 10965 2ad5 01/27 20:19:29 TN:00037 ######## ERROR: cvfwd_dispatch_one_tunnel(): Received invalid command from fd=12. Drop the socket. 10965 2ad5 01/27 20:19:29 TN:00039 ######## ERROR: cvfwd_dispatch_one_tunnel(): Received invalid command from fd=14. Drop the socket. 10965 2ad5 01/27 20:19:29 TN:00038 ######## ERROR: cvfwd_dispatch_one_tunnel(): Received invalid command from fd=13. Drop the socket. 10965 2ad5 01/27 20:19:29 TN:00040 ######## ERROR: cvfwd_dispatch_one_tunnel(): Received invalid command from fd=12. Drop the socket. 10965 2ad5 01/27 20:19:29 TN:00041 ######## ERROR: cvfwd_dispatch_one_tunnel(): Received invalid command from fd=12. Drop the socket. 10965 2ad5 01/27 20:19:29 TN:00042 ######## ERROR: cvfwd_dispatch_one_tunnel(): Received invalid command from fd=12. Drop the socket. 10965 2ad5 01/27 20:19:30 TN:00043 ######## ERROR: cvfwd_dispatch_one_tunnel(): Received invalid command from fd=12. Drop the socket. 10965 2ad5 01/27 20:19:30 TN:00044 ######## ERROR: cvfwd_dispatch_one_tunnel(): Received invalid command from fd=12. Drop the socket. 10965 2ad5 01/27 20:19:30 TN:00045 ######## ERROR: cvfwd_dispatch_one_tunnel(): Received invalid command from fd=13. Drop the socket. 10965 2ad5 01/27 20:19:30 TN:00046 ######## ERROR: cvfwd_dispatch_one_tunnel(): Received invalid command from fd=12. Drop the socket. 10965 2ad5 01/27 20:19:30 TN:00047 ######## ERROR: cvfwd_dispatch_one_tunnel(): Received invalid command from fd=13. Drop the socket.

Hello, 

The case can be closed. 
We have checked the system again and it came out that there are still communication problems, because Log4J still generates an alarm in the firewall. We have checked the agent for Log4J and it is clean. This means for me that Commvault is not causing any problems here. 
Thanks for the support

Regards
Thomas

Hello, 

 

I need to reopen this post here. 
One of our customers has approached us again because we have a DB that cannot be backed up once the exception in the company firewall is removed. 
We have been able to fix most of the problems by applying the 11.20.90 patch.
However, one system continues to have problems. Here at the beginning of the backup the connection to the media agent is established, which is blocked immediately, because the firewall probably recognizes Log4J here. 
In our security scans, we also had Log4J on the components of the Commvault environment, which, as mentioned, could be resolved by applying the patch.
Some findings on the affected server only affect commvault:
For example, log4j is referenced in the libCvHadoop.so file

grep -a -iR log4j /opt/commvault/ /opt/commvault/Base/libCvHadoop.so:vector::_M_default_appendvector::_M_emplace_back_aux=.*\nw Content [%s]cvhadooputil.propertiescvjarsFailed to copy '%s' to '%s'util.hadoop.userutil.hadoop.configutil.hbase.userutil.hbase. configcvhadooplog4j.propertiescvhdfsutil.loglog4j.appender.R.Filecvhdfsutil_DEBUGLEVELEventManagerDEBUG, Rlog4j.rootLoggerINFO, R/etc/Priam/unknown%s%c%s%c%scvhdfs-util.jarFailed to get HDP version-Dcvutil.config.file=%s %s %s %s %s %swebserver. UtilServer-cpnHadoopRestUtilWaitTimeCurl initialization failedhttp://localhost: /REST/hadoopStop failed with error [%s]/REST/NULSOHSTXETXEOTENQACKalertbackspacenewlinevertical-tabform-feedcarriage-returnSOSIDLEDC1DC2DC3DC4NAKSYNETBCANEMSUBESCIS4IS3IS2IS1exclamation-markquotation-marknumber-signdollar-signpercent-signampersandapostropheleft-parenthesisright-parenthesisasteriskplus-. signcommahyphenperiodzerotwothreefourfivesixseveneightninesemicolonless-than-signequals-signgreater-than-signquestion-markcommercial-atDFGJPUVWYZleft-square-bracketbackslashright- square-bracketcircumflexunderscoregrave-accentijqzleft-curly-bracketvertical-lineright-curly-brackettildeDELalnumalphablankcntrlgraphlowerprintpunctupperxdigit+��: ��q�����������������

There are also references under /opt/commvault/CVMedia/11.0.0/Unix/:
 grep -a log4j /opt/commvault/CVMedia/11.0.0/Unix/ -R /opt/commvault/CVMedia/11.0.0/Unix/linux-x8664/BinaryInfo.xml: <Binary CheckSum="0xF62C241B" FileType="TEXT" InstallFlag="Install" InstallToPath="GxHomeDir/Base64/cvlog4j.properties" IsDriverBinary="False" Name="cvlog4j.properties" SizeInBytes="1109" SourcePath="linux-glibc2. 3-x86_64/BinaryPayLoad/cvlog4j.properties.gz" TransactionID="SP7_487154" UncompressedChecksum="0xC2A51CD0"/> /opt/commvault/CVMedia/11.0.0/Unix/linux-x8664/BinaryInfo.xml: <Binary CheckSum="0x8A04E7C6" FileType="LIB" InstallFlag="Install" InstallToPath="GxHomeDir/Base64/DbJars/log4j-1.2.16.jar" IsDriverBinary="False" Name="log4j-1.2.16. jar" SizeInBytes="481534" SourcePath="linux-glibc2.3-x86_64/BinaryPayLoad/log4j-1.2.16.jar.gz" TransactionID="SP0_0" UncompressedChecksum="0xA77EF8EF"/> /opt/commvault/CVMedia/11.0.0/Unix/linux-x8664/BinaryInfo.xml: <Binary CheckSum="0x43441DE6" FileType="LIB" InstallFlag="Install" InstallToPath="GxHomeDir/Base64/DbJars/log4j-api-2.3.jar" IsDriverBinary="False" Name="log4j-api-2.3.jar" SizeInBytes="150741" SourcePath="linux-glibc2. 3-x86_64/BinaryPayLoad/log4j-api-2.3.jar.gz" TransactionID="SP2a_94701" UncompressedChecksum="0x6174D42F"/> /opt/commvault/CVMedia/11.0.0/Unix/linux-x8664/BinaryInfo.xml: <Binary CheckSum="0x7AEEF02B" FileType="LIB" InstallFlag="Install" InstallToPath="GxHomeDir/Base64/DbJars/log4j-core-2.3.jar" IsDriverBinary="False" Name="log4j-core-2.3.jar" SizeInBytes="893657" SourcePath="linux-glibc2. 3-x86_64/BinaryPayLoad/log4j-core-2.3.jar.gz" TransactionID="SP2a_94701" UncompressedChecksum="0xAA17564E"/> /opt/commvault/CVMedia/11.0.0/Unix/linux-x8664/BinaryInfo.xml: <Binary CheckSum="0x20A398FB" FileType="TEXT" InstallFlag="Install" InstallToPath="GxHomeDir/Base64/cvjars/cvhadooplog4j.properties" IsDriverBinary="False" Name="cvhadooplog4j. properties" SizeInBytes="530" SourcePath="linux-glibc2.3-x86_64/BinaryPayLoad/cvhadooplog4j.properties.gz" TransactionID="SP13_1331428" UncompressedChecksum="0x1466A052"/>

What else could be tried to find a solution here ? 

with kind regards

Thomas

Hi Thomas,

It looks like environmental issue. can you open a case with Commvault support so we can go through the logs and get back to you.

Regards,

Brahma

@thomas.S , I unmarked the best answer.  Can you share the case number once you have one created?

Thanks!!

Hi @Brahma, @Mike Struening 

I'm starting to think so, too. I have opened a case. Logs I would then have to try to provide tomorrow, because we would have to collect them again. Currently the backup is running because an exception rule has been set in the firewall. However, this rule must be removed again.

Incident 220223-633

Regards

Thomas

Moved encryption question to its own thread: