Problems with "Test SFTP" on MediaSense Archiving Configuration Page

Introduction

This document describes how to resolve a Secure SHell (SSH) algorithm negotiation failure that may occur when you are configuring a Secure File Transfer Protocol (SFTP) server to archive Cisco MediaSense (MS) recordings.

Prerequisites

Requirements

Cisco recommends that you have knowledge of these topics:

• Cisco MediaSense
• Linux server administration

Components Used

The information in this document is based on Cisco MediaSense version 10.5.1 and above.

The information in this document was created from the devices in a specific lab environment. All of the devices used in this document started with a cleared (default) configuration. If your network is live, make sure that you understand the potential impact of any command.

Problem: Test SFTP Button Fails Due to an SSH Algorithm Negotiation Failure

When you click on the Test SFTP button to test the Secure File Transfer Protocol (SFTP) connection for a Linuxed-based SFTP server on the MediaSense Archiving Configuration page, as shown in the image, you receive an error message that reads: "A General Error occurred. Contact your Administrator for more details."

Note: Any linux server may be used as an SFTP server.

In order to understand why the SFTP server connection failed, you need to examine the ORA-oraadmin logs located in /ora/logs/oraadmin folder from the MediaSense logs. These logs can be downloaded through Real Time Monitoring Tool (RTMT) when you select the MediaSense Administration process from Collect Files.

Solution

Look in the ORA-oraadmin logs for the SFTP configuration that is saved and the result of the Test SFTP button test.

You get a request to update archive configuration. The SFTP server has IP 10.1.2.25.

0000000387: 10.1.2.3: Jul 12 2016 14:43:09.168 -0500: %CCBU_COMMON-6-COMMON_SS_CFG_REQ: 
{Thrd=http-bio-443-exec-14} %[destination=topic://<RD>.<BUILDNUM>.Broadcast.CFG]
[message=SetPropertiesRequest[Request,properties=[
[node=0,name=basicArchiving.0.hostname,value=10.1.2.25,lastModified=1468352589168], 
[node=0,name=basicArchiving.appTypeArchiving.enabled,value=,lastModified=1468352589168],
[node=0,name=basicArchiving.audioArchiving.enabled,value=1,lastModified=1468352589168], 
[node=0,name=basicArchiving.0.bandWidthInKB,value=256,lastModified=1468352589168], 
[node=0,name=basicArchiving.0.password,value=xxxxxxxxxxxxxx==,lastModified=1468352589168], 
[node=0,name=basicArchiving.0.path,value=/home/mediasense,lastModified=1468352589168], 
[node=0,name=basicArchiving.archiveSessionAgedInDays,value=31,lastModified=1468352589168], 
[node=0,name=basicArchiving.startTimeInMinutes,value=60,lastModified=1468352589168], 
[node=0,name=basicArchiving.0.transferConnectionCount,value=3,lastModified=1468352589168], 
[node=0,name=basicArchiving.0.username,value=mediasense,lastModified=1468352589168], 
[node=0,name=basicArchiving.videoArchiving.enabled,value=0,lastModified=1468352589168], 
[node=0,name=basicArchiving.searchArchiving.enabled,value=1,lastModified=1468352589168], 
[node=0,name=basicArchiving.0.ssh.username,value=mediasense,lastModified=1468352589168], 
[node=0,name=basicArchiving.0.ssh.password,value=xxxxxxxxxxxxxx==,
lastModified=1468352589168]
],seqnum=43,header=MessageHeader[jmsType=ORA.CFG.SetPropertiesRequest,id=null,
corrId=null,ssId=ADMIN1,ssType=ADMIN,
dest=null,replyTo=<RD>.<BUILDNUM>.ReplyTo.<NODEID>.<SVC>.<SSID>,kind=NORMAL,
msgVersion=[1, 1, 1],timestamps={created=1468352589167}],state=CREATED,sequenced=false,
msg={null}]]: Config request published

0000000388: 10.1.2.3: Jul 12 2016 14:43:09.326 -0500: 
%CCBU_COMMON-6-MediaSenseG_INCOMING_FROM_BUS: {Thrd=ActiveMQ Session Task-7} 
%[correlation_id=null][mid=ID:msense01-59430-1468291227694-3:3:2:1:22]
[msg_kind=ActiveMQMapMessage][msg_type=ORA.CFG.PropertiesUpdatedEvent]: 
A message has been received by the message bus

0000000614: 10.1.2.3: Jul 12 2016 14:43:09.329 -0500: 
%CCBU_ADMIN-6-MediaSenseG_CANCEL_REQUEST: {Thrd=ActiveMQ Session Task-6} 
%[correlation_id=null][mid=null][msg_always_deliver_response=false]
[msg_kind=TIMEOUT][msg_req_id=ADMIN.ADMIN1.1468352589168.12]
[msg_type=ORA.CFG.SetPropertiesResponse]: 
A timeout for a pending request has been cancelled.

0000000615: 10.1.2.3: Jul 12 2016 14:43:09.330 -0500: %CCBU_ADMIN-7-PRE_RETURN: 
{Thrd=ActiveMQ Session Task-6} Starting message return, 
type = ORA.CFG.SetPropertiesResponse, corr_id = null

0000000615: 10.1.2.3: Jul 12 2016 14:43:09.330 -0500: %CCBU_ADMIN-7-PRE_RETURN: 
{Thrd=ActiveMQ Session Task-6} Starting message return, 
type = ORA.CFG.SetPropertiesResponse, corr_id = null

0000000389: 10.1.2.3: Jul 12 2016 14:43:09.330 -0500: %CCBU_COMMON-7-PRE_DISPATCH: 
{Thrd=ActiveMQ Session Task-7} Starting message dispatch, 
type = ORA.CFG.PropertiesUpdatedEvent, corr_id = null

0000000390: 10.1.2.3: Jul 12 2016 14:43:09.331 -0500: 
%CCBU_COMMON-7-INCOMING_MediaSenseG: {Thrd=ActiveMQ Session Task-7} 
PropertiesUpdatedHandler:sequenceImpl(com.cisco.ccbu.infra.msg.MediaSenseGDispatcher$
1@5db368): ORA.CFG.PropertiesUpdatedEvent

The response to update the configuration is Success, which means the configuration is properly set.

0000000391: 10.1.2.3: Jul 12 2016 14:43:09.331 -0500: 
%CCBU_COMMON-6-COMMON_SS_CFG_MediaSenseG: {Thrd=http-bio-443-exec-14} 
%[message=SetPropertiesResponse[Response,status=SUCCESS,properties=[
[node=0,name=basicArchiving.0.hostname,value=10.1.2.25,lastModified=1468352589177], 
[node=0,name=basicArchiving.appTypeArchiving.enabled,value=,lastModified=1468352589177],
[node=0,name=basicArchiving.audioArchiving.enabled,value=1,lastModified=1468352589177],
[node=0,name=basicArchiving.0.bandWidthInKB,value=256,lastModified=1468352589177], 
[node=0,name=basicArchiving.0.password,value=xxxxxxxxxxxxxx==,lastModified=1468352589177], 
[node=0,name=basicArchiving.0.path,value=/home/mediasense,lastModified=1468352589177], 
[node=0,name=basicArchiving.archiveSessionAgedInDays,value=31,lastModified=1468352589177], 
[node=0,name=basicArchiving.startTimeInMinutes,value=60,lastModified=1468352589177], 
[node=0,name=basicArchiving.0.transferConnectionCount,value=3,lastModified=1468352589177], 
[node=0,name=basicArchiving.0.username,value=mediasense,lastModified=1468352589177], 
[node=0,name=basicArchiving.videoArchiving.enabled,value=0,lastModified=1468352589177], 
[node=0,name=basicArchiving.searchArchiving.enabled,value=1,lastModified=1468352589177], 
[node=0,name=basicArchiving.0.ssh.username,value=mediasense,lastModified=1468352589177], 
[node=0,name=basicArchiving.0.ssh.password,value=xxxxxxxxxxxxxx==,lastModified=1468352589177], 
[node=0,name=node.last.modified,value=1468352589177,lastModified=1468352589177]
],seqnum=45,header=MessageHeader[

... //Lines Deleted for brevity//

]: Config message received

A connection request is made by the MediaSense administration service to connect to the SFTP server.

0000000629: 10.1.2.3: Jul 12 2016 14:43:13.431 -0500: %CCBU_ADMIN-6-GENERAL_LOG: 
{Thrd=http-bio-443-exec-14} %[message_string=ArchiveConfigurationAction : connect(): 
- in the method call]: oraadmin general log.

The MediaSense server tries to connect to the SFTP server 10.1.2.25.

0000000630: 10.1.2.3: Jul 12 2016 14:43:13.431 -0500: %CCBU_ADMIN-6-GENERAL_LOG: 
{Thrd=http-bio-443-exec-14} %[message_string=ArchiveConfigurationAction : connect(): 
Connecting to server :: 10.1.2.25]: oraadmin general log. 

0000000631: 10.1.2.3: Jul 12 2016 14:43:13.431 -0500: %CCBU_ADMIN-6-GENERAL_LOG: 
{Thrd=http-bio-443-exec-14} %[message_string=ArchiveConfigurationAction : 
testSftpConnection - in the method call]: oraadmin general log. 

The connection failes due to an Algorithm Negotiation Failure.

0000000632: 10.1.2.3: Jul 12 2016 14:43:13.632 -0500: %CCBU_ADMIN-6-GENERAL_LOG: 
{Thrd=http-bio-443-exec-14} %[message_string=ArchiveConfigurationAction : connect(): 
Cause ::Algorithm negotiation fail]: oraadmin general log.

A JSch (Java Secure Channel) connection failure occurs, where JSch is the Java Implementation of SSH that MediaSense uses to connect to an SSHD (Secure Shell Daemon) server (i.e. an SFTP server).

0000000633: 10.1.2.3: Jul 12 2016 14:43:13.632 -0500: %CCBU_ADMIN-6-GENERAL_LOG: 
{Thrd=http-bio-443-exec-14} %[message_string=ArchiveConfigurationAction : connect(): 
:: Error with JSch connection]: oraadmin general log. 

0000000634: 10.1.2.3: Jul 12 2016 14:43:13.632 -0500: %CCBU_ADMIN-7-EXCEPTION: 
{Thrd=http-bio-443-exec-14} Trace exception: com.jcraft.jsch.JSchException: 
Algorithm negotiation fail .

0000000635: 10.1.2.3: Jul 12 2016 14:43:13.633 -0500: %CCBU_ADMIN-7-EXCEPTION_INFO: 
%[build_date=Jan 17, 1970 8:05 AM][build_type=rel]
[exception=com.jcraft.jsch.JSchException: Algorithm negotiation fail
 at com.jcraft.jsch.Session.receive_kexinit(Session.java:583)
 at com.jcraft.jsch.Session.connect(Session.java:320)
 at com.jcraft.jsch.Session.connect(Session.java:183)
 at com.cisco.ora.oraadmin.presentation.action.configuration.archiveconfig.ArchiveConfigurationAction.newSession(ArchiveConfigurationAction.java:331)
 at com.cisco.ora.oraadmin.presentation.action.configuration.archiveconfig.ArchiveConfigurationAction.testSftpConnection(ArchiveConfigurationAction.java:294)
 at com.cisco.ora.oraadmin.presentation.action.configuration.archiveconfig.ArchiveConfigurationAction.connect(ArchiveConfigurationAction.java:175)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke(Method.java:606)
 at org.apache.struts.actions.DispatchAction.dispatchMethod(DispatchAction.java:276)
 at org.apache.struts.actions.DispatchAction.execute(DispatchAction.java:196)
 at com.cisco.ora.oraadmin.presentation.action.ExtendedDispatchAction.execute(ExtendedDispatchAction.java:115)
 at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:421)
 at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:226)
 at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1164)
 at org.apache.struts.action.ActionServlet.doPost(ActionServlet.java:415)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:647)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
 at com.cisco.vos.platform.tomcat.valves.CiscoResponseHeaderFilter.doFilter(Unknown Source)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
 at com.cisco.ccm.common.security.ChangePasswordFilter.doFilter(ChangePasswordFilter.java:86)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
 at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:222)
 at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123)
 at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:581)
 at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
 at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99)
 at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:953)
 at org.apache.catalina.authenticator.SingleSignOn.invoke(SingleSignOn.java:341)
 at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
 at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
 at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1023)
 at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:589)
 at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:312)
 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
 at java.lang.Thread.run(Thread.java:744)
][product_name=MediaSense][subsystem_exception_info=][tid=http-bio-443-exec-14]
[version_number=MediaSense_9_0_1_0_0_0_902]: Information associated with the following 
logged exception

In order to find out why this error is thrown, you need to analyze the packet capture traffic which comes in on the MediaSense server from the SFTP server. To do so, perform these steps:

1. Open the MediaSense archive configuration page.
   
   
2. On the MediaSense CLI, enter the these command: 
   utils network capture eth0 file packets count 100000 size all host ip <IP_of_SFTP_Server>
   
   
3. Click the Test SFTP button on the MediaSense archive configuration page and wait for the test to fail.
   
   
4. After the test fails, hit ctrl + C on your MediaSense CLI to stop the packet capture.
   
   
5. Pull the packet capture from RTMT. 

See https://supportforums.cisco.com/document/44376/packet-capture-cucm-appliance-model for more details.

This message will be thrown if MediaSense and your SFTP server cannot agree on a key exchange (KEX) algorithm, cipher for encrypting traffic, or Message Authentication Code (MAC) algorithm. These are the algorithms you must check in the packet capture. You need to ensure that the MediaSense server and the SFTP server both negotiate at least one of the same key exchange algorithm, cipher, and MAC algorithm. You must use the packet capture to see which algorithm is not being negotiated, and make sure your SFTP server negotiates one or more of the missing algorithms. 

If you don't want to look at a packet capture, you can ensure this configuration on your Linux-based SFTP server: 

1. Ensure that your SFTP server negotiates with MediaSense at least one of these options for key exchange algorithms:

diffie-hellman-group1-sha1,diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1

2. Ensure that your SFTP server negotiates with MediaSense at least one of these options for ciphers:

aes128-cbc,3des-cbc,blowfish-cbc,aes192-cbc,aes256-cbc

3. Ensure your SFTP server negotiates with MediaSense at least one of these options for MAC algorithms:

hmac-md5,hmac-sha1,hmac-sha2-256,hmac-sha1-96,hmac-md5-96

This can be set in your Linux-based SFTP server from the sshd_config file (SSH Daemon config).

For example, if your SFTP server does not negotiate a needed cipher, you can make it negotiate this by adding this line to the sshd_config configuration file on your SFTP server.

Cipher
aes128-cbc

Note: You can add any and all ciphers if necessary. Just separate with commas.

Bugs

Please note that documentation is being improved to make this process more clear.

See documentation defects CSCva50796 and CSCva66290.

Related Information

This is a link to man pages documentation for the sshd_config file that explains how to make configuration changes to your Linux-based SFTP server: http://manpages.ubuntu.com/manpages/wily/man5/sshd_config.5.html. 

This file is located at /etc/ssh/sshd_config. The same configuration changes are valid for any Linux server.