UmsPolly (Polly Plugin) with Proxy server issue

88 views
Skip to first unread message

Daniel Ng

unread,
Jul 13, 2021, 4:53:56 AM7/13/21
to UniMRCP
Dear Arsen, all,

Found a weird issue in which the Unimrcp logs would indicate that it was using the configured proxy settings and even report that it connected but a tcpdump showed no traffic out to the proxy.

In case of platform/user configuration error, I did a test using curl on the command line and verified that I got a tcpdump capture/trace for that test.

So my umspolly.xml contained the following lines that were updated from the standard umspolly.xml file (IP addresses partially redacted):
<umspolly license-file="umspolly_*.lic" credentials-file="aws.credentials" credentials-provider="custom" init-sdk="true" shutdown-sdk="false" sdk-log-level="6">
<synth-settings
      language="en-GB"
      bypass-ssml="true"
      voice-name="Emma"
      voice-gender="female"
      voice-engine=""
      prosody-pitch=""
      prosody-rate=""
      prosody-duration=""
      prosody-volume=""
      thread-pool-size="1"
      region="eu-west-2"
      caching="false"
      proxy-host="86.54.150.xxx"
      proxy-port="8080"
   />

To make the log file easier to read, I had also changed the logger.xml file to the following settings:
 <sources>
    <source name="MPF" priority="NOTICE" masking="NONE"/>
    <source name="UNIRTSP" priority="ERROR" masking="NONE"/>
    <source name="SOFIASIP" priority="ERROR" masking="NONE"/>
    <source name="LEX-PLUGIN" priority="ERROR" masking="NONE"/>
    <source name="POLLY-PLUGIN" priority="DEBUG" masking="NONE"/>
  </sources>

Platform itself is a CentOSv7 VM which I've checked is fully updated.  

The Unimrcpserver logs showed the following parts:
2021-07-12 15:13:33:945345 [NOTICE] Run as Daemon
2021-07-12 15:13:33:945393 [NOTICE] UniMRCP Server [1.7.0]
2021-07-12 15:13:33:945398 [INFO]   APR [1.5.2]
2021-07-12 15:13:33:945407 [NOTICE] Create MRCP Server
2021-07-12 15:13:33:945442 [NOTICE] Open Config File [/opt/unimrcp/conf/unimrcpserver.xml]
2021-07-12 15:13:33:946377 [INFO]   Set Property ip:172.xx.xxx.14
2021-07-12 15:13:33:946425 [NOTICE] Register Resource [speechsynth]
2021-07-12 15:13:33:946436 [NOTICE] Register Resource [speechrecog]
2021-07-12 15:13:33:946440 [NOTICE] Register Resource [recorder]
2021-07-12 15:13:33:946449 [NOTICE] Register Resource [speakverify]
2021-07-12 15:13:33:946453 [INFO]   Register Resource Factory
2021-07-12 15:13:33:946476 [INFO]   Register Signaling Agent [SIP-Agent-1]
2021-07-12 15:13:33:946494 [NOTICE] Create RTSP Server [RTSP-Agent-1] 172.xx.xxx.14:1554 [100] connection timeout [600 sec]
2021-07-12 15:13:33:946986 [INFO]   Register Signaling Agent [RTSP-Agent-1]
2021-07-12 15:13:33:947004 [NOTICE] Create MRCPv2 Agent [MRCPv2-Agent-1] 172.xx.xxx.14:1544 [100]
2021-07-12 15:13:33:947050 [INFO]   Register Connection Agent [MRCPv2-Agent-1]
2021-07-12 15:13:33:947057 [NOTICE] Create Media Engine [Media-Engine-1]
2021-07-12 15:13:33:947063 [INFO]   Register Media Engine [Media-Engine-1]
2021-07-12 15:13:33:947069 [NOTICE] Create RTP Termination Factory 172.xx.xxx.14:[5000,6000]
2021-07-12 15:13:33:947072 [INFO]   Register RTP Termination Factory [RTP-Factory-1]
2021-07-12 15:13:33:947078 [INFO]   Load Plugin [Demo-Verifier-1] [/opt/unimrcp/plugin/demoverifier.so]
2021-07-12 15:13:33:947194 [INFO]   Register MRCP Engine [Demo-Verifier-1]
2021-07-12 15:13:33:947205 [INFO]   Load Plugin [Recorder-1] [/opt/unimrcp/plugin/mrcprecorder.so]
2021-07-12 15:13:33:947267 [INFO]   Register MRCP Engine [Recorder-1]
2021-07-12 15:13:33:947275 [INFO]   Load Plugin [Lex-1] [/opt/unimrcp/plugin/umslex.so]
2021-07-12 15:13:33:962880 [INFO]   Register MRCP Engine [Lex-1]
2021-07-12 15:13:33:962895 [INFO]   Load Plugin [Polly-1] [/opt/unimrcp/plugin/umspolly.so]
2021-07-12 15:13:33:964279 [NOTICE] POLLY Plugin Version [1.8.1] Date [2021-06-11]
2021-07-12 15:13:33:964436 [INFO]   Register MRCP Engine [Polly-1]
2021-07-12 15:13:33:964452 [INFO]   Register RTP Settings [RTP-Settings-1]
2021-07-12 15:13:33:964459 [NOTICE] Create MRCPv2 Profile [uni2]
2021-07-12 15:13:33:964467 [INFO]   Associate Resource [speechsynth] to Engine [Polly-1] in Profile [uni2]
2021-07-12 15:13:33:964471 [INFO]   Associate Resource [speechrecog] to Engine [Lex-1] in Profile [uni2]
2021-07-12 15:13:33:964474 [INFO]   Associate Resource [recorder] to Engine [Recorder-1] in Profile [uni2]
2021-07-12 15:13:33:964477 [INFO]   Associate Resource [speakverify] to Engine [Demo-Verifier-1] in Profile [uni2]
2021-07-12 15:13:33:964480 [INFO]   Register Profile [uni2]
2021-07-12 15:13:33:964484 [NOTICE] Create MRCPv1 Profile [uni1]
2021-07-12 15:13:33:964487 [INFO]   Associate Resource [speechsynth] to Engine [Polly-1] in Profile [uni1]
2021-07-12 15:13:33:964490 [INFO]   Associate Resource [speechrecog] to Engine [Lex-1] in Profile [uni1]
2021-07-12 15:13:33:964493 [INFO]   Associate Resource [recorder] to Engine [Recorder-1] in Profile [uni1]
2021-07-12 15:13:33:964496 [INFO]   Associate Resource [speakverify] to Engine [Demo-Verifier-1] in Profile [uni1]
2021-07-12 15:13:33:964498 [INFO]   Register Profile [uni1]
2021-07-12 15:13:33:964502 [INFO]   Start Task [MRCP Server]
2021-07-12 15:13:33:965029 [INFO]   Open Engine [Polly-1]
2021-07-12 15:13:33:965065 [NOTICE] Open Config File [/opt/unimrcp/conf/umspolly.xml]
2021-07-12 15:13:33:965247 [DEBUG]  Load Document Attribute: sdk-log-level = 6
2021-07-12 15:13:33:965256 [DEBUG]  Load Document Attribute: shutdown-sdk = false
2021-07-12 15:13:33:965259 [DEBUG]  Load Document Attribute: init-sdk = true
2021-07-12 15:13:33:965262 [DEBUG]  Load Document Attribute: credentials-provider = custom
2021-07-12 15:13:33:965266 [DEBUG]  Load Document Attribute: credentials-file = aws.credentials
2021-07-12 15:13:33:965269 [DEBUG]  Load Document Attribute: license-file = umspolly_*.lic
2021-07-12 15:13:33:965278 [DEBUG]  Loading Element license-server
2021-07-12 15:13:33:965287 [DEBUG]  Loading Element synth-settings
2021-07-12 15:13:33:965292 [DEBUG]  Load Synth Attribute: proxy-port = 8080
2021-07-12 15:13:33:965296 [DEBUG]  Load Synth Attribute: proxy-host = 86.54.150.xxx
2021-07-12 15:13:33:965300 [DEBUG]  Load Synth Attribute: caching = false
2021-07-12 15:13:33:965303 [DEBUG]  Load Synth Attribute: region = eu-west-2
2021-07-12 15:13:33:965306 [DEBUG]  Load Synth Attribute: thread-pool-size = 1
2021-07-12 15:13:33:965309 [DEBUG]  Load Synth Attribute: prosody-volume = 
2021-07-12 15:13:33:965312 [DEBUG]  Load Synth Attribute: prosody-duration = 
2021-07-12 15:13:33:965315 [DEBUG]  Load Synth Attribute: prosody-rate = 
2021-07-12 15:13:33:965318 [DEBUG]  Load Synth Attribute: prosody-pitch = 
2021-07-12 15:13:33:965320 [DEBUG]  Load Synth Attribute: voice-engine = 
2021-07-12 15:13:33:965323 [DEBUG]  Load Synth Attribute: voice-gender = female
2021-07-12 15:13:33:965326 [DEBUG]  Load Synth Attribute: voice-name = Emma
2021-07-12 15:13:33:965329 [DEBUG]  Load Synth Attribute: bypass-ssml = true
2021-07-12 15:13:33:965332 [DEBUG]  Load Synth Attribute: language = en-GB
2021-07-12 15:13:33:965335 [DEBUG]  Loading Element waveform-manager
2021-07-12 15:13:33:965340 [DEBUG]  Load Waveform Manager Attribute: use-logging-tag = false
2021-07-12 15:13:33:965343 [DEBUG]  Load Waveform Manager Attribute: waveform-folder = 
2021-07-12 15:13:33:965346 [DEBUG]  Load Waveform Manager Attribute: max-file-count = 100
2021-07-12 15:13:33:965349 [DEBUG]  Load Waveform Manager Attribute: max-file-age = 60
2021-07-12 15:13:33:965352 [DEBUG]  Load Waveform Manager Attribute: purge-existing = false
2021-07-12 15:13:33:965355 [DEBUG]  Load Waveform Manager Attribute: save-waveforms = false
2021-07-12 15:13:33:965358 [DEBUG]  Loading Element sdr-manager
2021-07-12 15:13:33:965362 [DEBUG]  Load SDR Manager Attribute: use-logging-tag = false
2021-07-12 15:13:33:965367 [DEBUG]  Load SDR Manager Attribute: record-folder = 
2021-07-12 15:13:33:965370 [DEBUG]  Load SDR Manager Attribute: max-file-count = 100
2021-07-12 15:13:33:965372 [DEBUG]  Load SDR Manager Attribute: max-file-age = 60
2021-07-12 15:13:33:965375 [DEBUG]  Load SDR Manager Attribute: purge-existing = false
2021-07-12 15:13:33:965378 [DEBUG]  Load SDR Manager Attribute: save-records = false
2021-07-12 15:13:33:965381 [DEBUG]  Loading Element monitoring-agent
2021-07-12 15:13:33:965384 [DEBUG]  Load Monitoring Attribute: refresh-period = 60
2021-07-12 15:13:33:965387 [DEBUG]  Load Log Statement Attribute: priority = NOTICE
2021-07-12 15:13:33:965390 [DEBUG]  Load Log Statement Attribute: enable = true
2021-07-12 15:13:33:965394 [DEBUG]  Load Status File Attribute: status-file = umspolly-usage.status
2021-07-12 15:13:33:965397 [DEBUG]  Load Status File Attribute: enable = false
2021-07-12 15:13:33:965400 [DEBUG]  Load Status File Attribute: status-file = umspolly-channels.status
2021-07-12 15:13:33:965403 [DEBUG]  Load Status File Attribute: enable = false
2021-07-12 15:13:33:965406 [DEBUG]  Load Log Statement Attribute: priority = NOTICE
2021-07-12 15:13:33:965409 [DEBUG]  Load Log Statement Attribute: enable = false
2021-07-12 15:13:33:965412 [DEBUG]  Load Status File Attribute: status-file = umspolly-usage.status
2021-07-12 15:13:33:965415 [DEBUG]  Load Status File Attribute: enable = false
2021-07-12 15:13:33:965418 [DEBUG]  Load Status File Attribute: status-file = umspolly-channels.status
2021-07-12 15:13:33:965421 [DEBUG]  Load Status File Attribute: enable = false
2021-07-12 15:13:33:965862 [NOTICE] Determined License File /opt/unimrcp/data/umspolly_69118ade-dc0f-4401-b164-bd45c05fdf40.lic
2021-07-12 15:13:33:966070 [NOTICE] Init AWS API [1.8.129]
2021-07-12 15:13:33:966213 [INFO]   [INFO] 2021-07-12 14:13:33.966 Aws_Init_Cleanup [140325050259200] Initiate AWS SDK for C++ with Version:1.8.129

2021-07-12 15:13:33:966239 [INFO]   [TRACE] 2021-07-12 14:13:33.966 FileSystemUtils [140325050259200] Checking HOME for the home directory.

2021-07-12 15:13:33:966252 [INFO]   [DEBUG] 2021-07-12 14:13:33.966 FileSystemUtils [140325050259200] Environment value for variable HOME is 

2021-07-12 15:13:33:966259 [INFO]   [WARN] 2021-07-12 14:13:33.966 FileSystemUtils [140325050259200] Home dir not stored in environment, trying to fetch manually from the OS.

2021-07-12 15:13:33:966423 [INFO]   [INFO] 2021-07-12 14:13:33.966 FileSystemUtils [140325050259200] Pulled /root as home directory from the OS.

2021-07-12 15:13:33:966441 [INFO]   [DEBUG] 2021-07-12 14:13:33.966 FileSystemUtils [140325050259200] Home directory is missing the final / appending one to normalize
...
2021-07-12 15:13:33:968080 [INFO]   Open Engine [Recorder-1]
2021-07-12 15:13:33:968092 [INFO]   Open Engine [Lex-1]
2021-07-12 15:13:33:968093 [NOTICE] Polly Usage: 0/0/0
2021-07-12 15:13:33:968572 [INFO]   Open Engine [Demo-Verifier-1]
2021-07-12 15:13:33:968583 [INFO]   Start Task [Demo Verifier Engine]
2021-07-12 15:13:33:968609 [INFO]   Start Task [SIP-Agent-1]
2021-07-12 15:13:33:968630 [INFO]   Start Task [RTSP-Agent-1]
2021-07-12 15:13:33:968654 [INFO]   Start Task [MRCPv2-Agent-1]
2021-07-12 15:13:33:968678 [INFO]   Start Task [Media-Engine-1]
2021-07-12 15:13:33:969240 [NOTICE] UniMRCP Polly License 

-product name:    umspolly
-product version: 1.0.0
-license owner:   KCOM
-license type:    production
-issue date:      2021-06-30
-channel count:   2
-feature set:     0
...
2021-07-12 15:13:33:969376 [INFO]   [TRACE] 2021-07-12 14:13:33.969 EC2MetadataClient [140324961773312] Retrieving credentials from http://169.254.169.254/latest/meta-data/placement/availability-zone

2021-07-12 15:13:33:969391 [INFO]   [TRACE] 2021-07-12 14:13:33.969 EC2MetadataClient [140324953380608] Retrieving credentials from http://169.254.169.254/latest/meta-data/placement/availability-zone

2021-07-12 15:13:33:969403 [INFO]   [TRACE] 2021-07-12 14:13:33.969 CurlHttpClient [140324961773312] Making request to http://169.254.169.254/latest/meta-data/placement/availability-zone

2021-07-12 15:13:33:969413 [INFO]   [TRACE] 2021-07-12 14:13:33.969 CurlHttpClient [140324953380608] Making request to http://169.254.169.254/latest/meta-data/placement/availability-zone

2021-07-12 15:13:33:969416 [INFO]   [TRACE] 2021-07-12 14:13:33.969 CurlHttpClient [140324961773312] Including headers:

2021-07-12 15:13:33:969426 [INFO]   [TRACE] 2021-07-12 14:13:33.969 CurlHttpClient [140324953380608] Including headers:

2021-07-12 15:13:33:969434 [INFO]   [TRACE] 2021-07-12 14:13:33.969 CurlHttpClient [140324961773312] host: 169.254.169.254

2021-07-12 15:13:33:969437 [INFO]   [TRACE] 2021-07-12 14:13:33.969 CurlHttpClient [140324953380608] host: 169.254.169.254

2021-07-12 15:13:33:969447 [INFO]   [TRACE] 2021-07-12 14:13:33.969 CurlHttpClient [140324961773312] user-agent: aws-sdk-cpp/1.8.129 Linux/3.10.0-1160.31.1.el7.x86_64 x86_64 GCC/4.8.5

2021-07-12 15:13:33:969462 [INFO]   [TRACE] 2021-07-12 14:13:33.969 CurlHttpClient [140324961773312] x-aws-ec2-metadata-token: 

2021-07-12 15:13:33:969477 [INFO]   [DEBUG] 2021-07-12 14:13:33.969 CurlHandleContainer [140324961773312] Attempting to acquire curl connection.

2021-07-12 15:13:33:969485 [INFO]   [DEBUG] 2021-07-12 14:13:33.969 CurlHandleContainer [140324961773312] No current connections available in pool. Attempting to create new connections.

2021-07-12 15:13:33:969494 [INFO]   [DEBUG] 2021-07-12 14:13:33.969 CurlHandleContainer [140324961773312] attempting to grow pool size by 2

2021-07-12 15:13:33:969587 [INFO]   [INFO] 2021-07-12 14:13:33.969 CurlHandleContainer [140324961773312] Pool grown by 2

2021-07-12 15:13:33:969599 [INFO]   [INFO] 2021-07-12 14:13:33.969 CurlHandleContainer [140324961773312] Connection has been released. Continuing.

2021-07-12 15:13:33:969609 [INFO]   [DEBUG] 2021-07-12 14:13:33.969 CurlHandleContainer [140324961773312] Returning connection handle 0x7f9fec003c40

2021-07-12 15:13:33:969617 [INFO]   [DEBUG] 2021-07-12 14:13:33.969 CurlHttpClient [140324961773312] Obtained connection handle 0x7f9fec003c40

2021-07-12 15:13:33:969449 [INFO]   [TRACE] 2021-07-12 14:13:33.969 CurlHttpClient [140324953380608] user-agent: aws-sdk-cpp/1.8.129 Linux/3.10.0-1160.31.1.el7.x86_64 x86_64 GCC/4.8.5

2021-07-12 15:13:33:969686 [INFO]   [TRACE] 2021-07-12 14:13:33.969 CurlHttpClient [140324953380608] x-aws-ec2-metadata-token: 

2021-07-12 15:13:33:969700 [INFO]   [DEBUG] 2021-07-12 14:13:33.969 CurlHandleContainer [140324953380608] Attempting to acquire curl connection.

2021-07-12 15:13:33:969709 [INFO]   [INFO] 2021-07-12 14:13:33.969 CurlHandleContainer [140324953380608] Connection has been released. Continuing.

2021-07-12 15:13:33:969717 [INFO]   [DEBUG] 2021-07-12 14:13:33.969 CurlHandleContainer [140324953380608] Returning connection handle 0x7f9fec002350
...
2021-07-12 15:13:33:973700 [INFO]   [DEBUG] 2021-07-12 14:13:33.973 CURL [140324953380608] (Text)   Trying 169.254.169.254:80...


2021-07-12 15:13:33:973699 [INFO]   [DEBUG] 2021-07-12 14:13:33.973 CURL [140324961773312] (Text)   Trying 169.254.169.254:80...


2021-07-12 15:13:34:975050 [INFO]   [DEBUG] 2021-07-12 14:13:34.975 CURL [140324953380608] (Text) Connection timed out after 1001 milliseconds


2021-07-12 15:13:34:975051 [INFO]   [DEBUG] 2021-07-12 14:13:34.975 CURL [140324961773312] (Text) Connection timed out after 1001 milliseconds


2021-07-12 15:13:34:975209 [INFO]   [DEBUG] 2021-07-12 14:13:34.975 CURL [140324953380608] (Text) Closing connection 0


2021-07-12 15:13:34:975209 [INFO]   [DEBUG] 2021-07-12 14:13:34.975 CURL [140324961773312] (Text) Closing connection 0


2021-07-12 15:13:34:975287 [INFO]   [ERROR] 2021-07-12 14:13:34.975 CurlHttpClient [140324953380608] Curl returned error code 28 - Timeout was reached

2021-07-12 15:13:34:975303 [INFO]   [ERROR] 2021-07-12 14:13:34.975 CurlHttpClient [140324961773312] Curl returned error code 28 - Timeout was reached
...
2021-07-12 15:13:35:980568 [INFO]   [ERROR] 2021-07-12 14:13:35.980 EC2MetadataClient [140324953380608] Http request to retrieve credentials failed

2021-07-12 15:13:35:980609 [INFO]   [ERROR] 2021-07-12 14:13:35.980 EC2MetadataClient [140324953380608] Can not retrive resource from http://169.254.169.254/latest/meta-data/placement/availability-zone

2021-07-12 15:13:35:980631 [INFO]   [INFO] 2021-07-12 14:13:35.980 EC2MetadataClient [140324953380608] Unable to pull region from instance metadata service 

2021-07-12 15:13:35:981034 [INFO]   [INFO] 2021-07-12 14:13:35.981 CurlHandleContainer [140324953380608] Initializing CurlHandleContainer with size 25

2021-07-12 15:13:35:981875 [NOTICE] Populate files from /opt/unimrcp/var/ pattern [umslex-*.wav] max-count [100] max-age [60 min] purge-existing [0]
2021-07-12 15:13:35:981892 [NOTICE] Populate files from /opt/unimrcp/var/ pattern [umslex-*.json] max-count [100] max-age [60 min] purge-existing [0]
2021-07-12 15:13:35:983064 [INFO]   [DEBUG] 2021-07-12 14:13:35.983 CURL [140324961773312] (Text) Connection timed out after 1001 milliseconds


2021-07-12 15:13:35:983090 [INFO]   [DEBUG] 2021-07-12 14:13:35.983 CURL [140324961773312] (Text) Closing connection 0


2021-07-12 15:13:35:983115 [INFO]   [ERROR] 2021-07-12 14:13:35.983 CurlHttpClient [140324961773312] Curl returned error code 28 - Timeout was reached

2021-07-12 15:13:35:983191 [INFO]   [DEBUG] 2021-07-12 14:13:35.983 CurlHandleContainer [140324961773312] Destroy curl handle: 0x7f9fe4001dd0

2021-07-12 15:13:35:983209 [INFO]   [DEBUG] 2021-07-12 14:13:35.983 CurlHandleContainer [140324961773312] Created replacement handle and released to pool: 0x7f9fec00a1f0

2021-07-12 15:13:35:983220 [INFO]   [ERROR] 2021-07-12 14:13:35.983 EC2MetadataClient [140324961773312] Http request to retrieve credentials failed

2021-07-12 15:13:35:983237 [INFO]   [ERROR] 2021-07-12 14:13:35.983 EC2MetadataClient [140324961773312] Can not retrive resource from http://169.254.169.254/latest/meta-data/placement/availability-zone

2021-07-12 15:13:35:983246 [INFO]   [INFO] 2021-07-12 14:13:35.983 EC2MetadataClient [140324961773312] Unable to pull region from instance metadata service 

2021-07-12 15:13:35:983290 [INFO]   Set HTTP Proxy [86.54.150.xxx:8080]
2021-07-12 15:13:35:983300 [NOTICE] Read AWS Credentials /opt/unimrcp/data/aws.credentials
2021-07-12 15:13:35:983355 [INFO]   Create Polly Client: thread pool [1] region [eu-west-2]
2021-07-12 15:13:35:983395 [INFO]   [INFO] 2021-07-12 14:13:35.983 CurlHandleContainer [140324961773312] Initializing CurlHandleContainer with size 25

2021-07-12 15:13:35:983418 [INFO]   Describe Voices
2021-07-12 15:13:35:983470 [INFO]   [TRACE] 2021-07-12 14:13:35.983 AWSClient [140324961773312] No content body, content-length headers

2021-07-12 15:13:35:983491 [INFO]   [DEBUG] 2021-07-12 14:13:35.983 AWSAuthV4Signer [140324961773312] Using cached empty string sha256 e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 because payload is empty.

2021-07-12 15:13:35:983536 [INFO]   [DEBUG] 2021-07-12 14:13:35.983 AWSAuthV4Signer [140324961773312] Canonical Header String: amz-sdk-invocation-id:EE7CA66B-79D5-4868-ABE0-63302C52778A
amz-sdk-request:attempt=1
content-type:application/x-amz-json-1.1
x-amz-api-version:2016-06-10
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20210712T141335Z
2021-07-12 15:13:35:983544 [INFO]   [DEBUG] 2021-07-12 14:13:35.983 AWSAuthV4Signer [140324961773312] Signed Headers value:amz-sdk-invocation-id;amz-sdk-request;content-type;host;x-amz-api-version;x-amz-content-sha256;x-amz-date

2021-07-12 15:13:35:983574 [INFO]   [DEBUG] 2021-07-12 14:13:35.983 AWSAuthV4Signer [140324961773312] Canonical Request String: GET
/v1/voices
IncludeAdditionalLanguageCodes=0
amz-sdk-invocation-id:EE7CA66B-79D5-4868-ABE0-63302C52778A
amz-sdk-request:attempt=1
content-type:application/x-amz-json-1.1
x-amz-api-version:2016-06-10
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20210712T141335Z

amz-sdk-invocation-id;amz-sdk-request;content-type;host;x-amz-api-version;x-amz-content-sha256;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855

2021-07-12 15:13:35:983605 [INFO]   [DEBUG] 2021-07-12 14:13:35.983 AWSAuthV4Signer [140324961773312] Final String to sign: AWS4-HMAC-SHA256
20210712T141335Z
20210712/eu-west-2/polly/aws4_request
3f220f946b878b7c5a86061fdeb448ee611fc84803e240f4e93c1cdd37cd7d6e

2021-07-12 15:13:35:983617 [INFO]   [DEBUG] 2021-07-12 14:13:35.983 AWSAuthV4Signer [140324961773312] Final computed signing hash: 1a104c2984860a0f48602606d4514af2292c16e29c5e8953812511a34ea688d1

2021-07-12 15:13:35:983626 [INFO]   [DEBUG] 2021-07-12 14:13:35.983 AWSAuthV4Signer [140324961773312] Signing request with: AWS4-HMAC-SHA256 Credential=AKIA27PA2SGTLXQJPXTD/20210712/eu-west-2/polly/aws4_request, SignedHeaders=amz-sdk-invocation-id;amz-sdk-request;content-type;host;x-amz-api-version;x-amz-content-sha256;x-amz-date, Signature=1a104c2984860a0f48602606d4514af2292c16e29c5e8953812511a34ea688d1

2021-07-12 15:13:35:983636 [INFO]   [DEBUG] 2021-07-12 14:13:35.983 AWSClient [140324961773312] Request Successfully signed

2021-07-12 15:13:35:983650 [INFO]   [TRACE] 2021-07-12 14:13:35.983 CurlHttpClient [140324961773312] Making request to https://polly.eu-west-2.amazonaws.com/v1/voices?IncludeAdditionalLanguageCodes=0

2021-07-12 15:13:35:983660 [INFO]   [TRACE] 2021-07-12 14:13:35.983 CurlHttpClient [140324961773312] Including headers:

2021-07-12 15:13:35:983667 [INFO]   [TRACE] 2021-07-12 14:13:35.983 CurlHttpClient [140324961773312] amz-sdk-invocation-id: EE7CA66B-79D5-4868-ABE0-63302C52778A

2021-07-12 15:13:35:983674 [INFO]   [TRACE] 2021-07-12 14:13:35.983 CurlHttpClient [140324961773312] amz-sdk-request: attempt=1

2021-07-12 15:13:35:983681 [INFO]   [TRACE] 2021-07-12 14:13:35.983 CurlHttpClient [140324961773312] authorization: AWS4-HMAC-SHA256 Credential=AKIA27PA2SGTLXQJPXTD/20210712/eu-west-2/polly/aws4_request, SignedHeaders=amz-sdk-invocation-id;amz-sdk-request;content-type;host;x-amz-api-version;x-amz-content-sha256;x-amz-date, Signature=1a104c2984860a0f48602606d4514af2292c16e29c5e8953812511a34ea688d1

2021-07-12 15:13:35:983688 [INFO]   [TRACE] 2021-07-12 14:13:35.983 CurlHttpClient [140324961773312] content-type: application/x-amz-json-1.1

2021-07-12 15:13:35:983694 [INFO]   [TRACE] 2021-07-12 14:13:35.983 CurlHttpClient [140324961773312] host: polly.eu-west-2.amazonaws.com

2021-07-12 15:13:35:983700 [INFO]   [TRACE] 2021-07-12 14:13:35.983 CurlHttpClient [140324961773312] user-agent: aws-sdk-cpp/1.8.129/Polly/Linux/3.10.0-1160.31.1.el7.x86_64 x86_64 GCC/4.8.5

2021-07-12 15:13:35:983707 [INFO]   [TRACE] 2021-07-12 14:13:35.983 CurlHttpClient [140324961773312] x-amz-api-version: 2016-06-10

2021-07-12 15:13:35:983713 [INFO]   [TRACE] 2021-07-12 14:13:35.983 CurlHttpClient [140324961773312] x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855

2021-07-12 15:13:35:983720 [INFO]   [TRACE] 2021-07-12 14:13:35.983 CurlHttpClient [140324961773312] x-amz-date: 20210712T141335Z

2021-07-12 15:13:35:983728 [INFO]   [DEBUG] 2021-07-12 14:13:35.983 CurlHandleContainer [140324961773312] Attempting to acquire curl connection.

2021-07-12 15:13:35:983735 [INFO]   [DEBUG] 2021-07-12 14:13:35.983 CurlHandleContainer [140324961773312] No current connections available in pool. Attempting to create new connections.

2021-07-12 15:13:35:983741 [INFO]   [DEBUG] 2021-07-12 14:13:35.983 CurlHandleContainer [140324961773312] attempting to grow pool size by 2

2021-07-12 15:13:35:983759 [INFO]   [INFO] 2021-07-12 14:13:35.983 CurlHandleContainer [140324961773312] Pool grown by 2

2021-07-12 15:13:35:983766 [INFO]   [INFO] 2021-07-12 14:13:35.983 CurlHandleContainer [140324961773312] Connection has been released. Continuing.

2021-07-12 15:13:35:983772 [INFO]   [DEBUG] 2021-07-12 14:13:35.983 CurlHandleContainer [140324961773312] Returning connection handle 0x7f9fec004f80

2021-07-12 15:13:35:983779 [INFO]   [DEBUG] 2021-07-12 14:13:35.983 CurlHttpClient [140324961773312] Obtained connection handle 0x7f9fec004f80

2021-07-12 15:13:35:985419 [INFO]   [DEBUG] 2021-07-12 14:13:35.985 CURL [140324961773312] (Text)   Trying 86.54.150.xxx:8080...


2021-07-12 15:13:36:184842 [INFO]   [DEBUG] 2021-07-12 14:13:36.184 CURL [140324961773312] (Text) Connected to 86.54.150.xxx (86.54.150.xxx) port 8080 (#0)


2021-07-12 15:13:36:184935 [INFO]   [DEBUG] 2021-07-12 14:13:36.184 CURL [140324961773312] (Text) ALPN, offering http/1.1


2021-07-12 15:13:36:184991 [INFO]   [DEBUG] 2021-07-12 14:13:36.184 CURL [140324961773312] (Text) Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH


2021-07-12 15:13:36:191040 [INFO]   [DEBUG] 2021-07-12 14:13:36.191 CURL [140324961773312] (Text) successfully set certificate verify locations:


2021-07-12 15:13:36:191056 [INFO]   [DEBUG] 2021-07-12 14:13:36.191 CURL [140324961773312] (Text)  CAfile: /etc/pki/tls/certs/ca-bundle.crt


2021-07-12 15:13:36:191063 [INFO]   [DEBUG] 2021-07-12 14:13:36.191 CURL [140324961773312] (Text)  CApath: /etc/ssl/certs


2021-07-12 15:13:36:191251 [INFO]   [DEBUG] 2021-07-12 14:13:36.191 CURL [140324961773312] (Text) TLSv1.2 (OUT), TLS header, Certificate Status (22):


2021-07-12 15:13:36:191273 [INFO]   [DEBUG] 2021-07-12 14:13:36.191 CURL [140324961773312] (SSLDataOut) 5bytes

2021-07-12 15:13:36:191282 [INFO]   [DEBUG] 2021-07-12 14:13:36.191 CURL [140324961773312] (Text) TLSv1.2 (OUT), TLS handshake, Client hello (1):


2021-07-12 15:13:36:191288 [INFO]   [DEBUG] 2021-07-12 14:13:36.191 CURL [140324961773312] (SSLDataOut) 512bytes

2021-07-12 15:13:36:191595 [INFO]   [DEBUG] 2021-07-12 14:13:36.191 CURL [140324961773312] (Text) OpenSSL SSL_connect: SSL_ERROR_SYSCALL in connection to 86.54.150.xxx:8080 


2021-07-12 15:13:36:191608 [INFO]   [DEBUG] 2021-07-12 14:13:36.191 CURL [140324961773312] (Text) Closing connection 0


2021-07-12 15:13:36:192379 [INFO]   [ERROR] 2021-07-12 14:13:36.192 CurlHttpClient [140324961773312] Curl returned error code 35 - SSL connect error

2021-07-12 15:13:36:192449 [INFO]   [DEBUG] 2021-07-12 14:13:36.192 CurlHandleContainer [140324961773312] Destroy curl handle: 0x7f9fec004f80

2021-07-12 15:13:36:192465 [INFO]   [DEBUG] 2021-07-12 14:13:36.192 CurlHandleContainer [140324961773312] Created replacement handle and released to pool: 0x7f9fec004f80

2021-07-12 15:13:36:192476 [INFO]   [DEBUG] 2021-07-12 14:13:36.192 AWSClient [140324961773312] Request returned error. Attempting to generate appropriate error codes from response

2021-07-12 15:13:36:192494 [INFO]   [ERROR] 2021-07-12 14:13:36.192 AWSClient [140324961773312] HTTP response code: -1
Resolved remote host IP address: 86.54.150.xxx
Request ID: 
Exception name: 
Error message: curlCode: 35, SSL connect error
0 response headers:

2021-07-12 15:13:36:192511 [INFO]   [WARN] 2021-07-12 14:13:36.192 AWSClient [140324961773312] If the signature check failed. This could be because of a time skew. Attempting to adjust the signer.

2021-07-12 15:13:36:192520 [INFO]   [DEBUG] 2021-07-12 14:13:36.192 AWSClient [140324961773312] Date header was not found in the response, can't attempt to detect clock skew

As you can see in the log, it appeared that Unimrcp reports that it managed to connect to the proxy server and initiated the SSL Client Hello.  As part of troubleshooting this handshake issue, I attempted to use tcpdump to get a trace to see what is going on and this is where I found that there wasn't any network traffic going out of that server to the proxy (literally zero packets captured - tcpdump was against all network interfaces and against the proxy host IP address).  The above was trigger using the umc application and running the bss1 scenario.

In case there were some other platform issues, I took the URL from the log (the https://polly.eu-west-2.amazonaws.com/ one) and from a terminal on that same server (with and without tcpdump running), I used curl to test that URL and network connectivity to the proxy/from that server.  This generated a tcpdump trace (using the same command/options as when capturing for unimrcp) with packets captured and a response back from AWS too.

Basically umspolly plugin proxy code not working?

Any thoughts and suggestions welcomed especially in terms of getting more information out from the system as the unimrcp logs appear to be misleading at the moment?

Kind regards,
Daniel

Daniel Ng

unread,
Jul 29, 2021, 6:28:57 AM7/29/21
to UniMRCP
Hi Arsen,

Is there anyway of increasing the debugging level any further to see why the Unimrcp Polly proxy code is failing to connect?

I'm trying to figure out why I'm getting
2021-07-29 11:14:12:536337 [INFO]   Set HTTP Proxy [86.xx.xx.xx:8080]
2021-07-29 11:14:12:536396 [NOTICE] Read AWS Credentials /opt/unimrcp/data/aws.credentials
2021-07-29 11:14:12:536486 [INFO]   Create Polly Client: thread pool [1] region [eu-west-2]
2021-07-29 11:14:12:536636 [INFO]   Describe Voices
2021-07-29 11:14:40:460995 [WARN]   Failed to Describe Voices [curlCode: 35, SSL connect error]

I've turned off all firewalls on the platform (iptables) and ran a "tcpdump -i any host 86.xx.xx.xx" to see what is actually sent out from the platform but it is empty.
When I run curl from the command line to that same proxy, I do get data via the tcpdump command. 

In my umspolly.xml, I've set the sdk log level to 6
<umspolly license-file="umspolly_*.lic" credentials-file="aws.credentials" credentials-provider="custom" init-sdk="true" shutdown-sdk="false" sdk-log-level="6">

In my logger.xml file, I've got the following set:
  <sources>
    <source name="MPF" priority="NOTICE" masking="NONE"/>
    <source name="UNIRTSP" priority="WARNING" masking="NONE"/>
    <source name="SOFIASIP" priority="WARNING" masking="NONE"/>
    <source name="LEX-PLUGIN" priority="WARNING" masking="NONE"/>
    <source name="POLLY-PLUGIN" priority="DEBUG" masking="NONE"/>
  </sources>

Should the MPF be increased to e.g. DEBUG too?

I've also checked the ntp settings to ensure that the system time is sync'ed 

Kind regards,
Daniel

Arsen Chaloyan

unread,
Aug 24, 2021, 9:59:36 PM8/24/21
to UniMRCP
Hi Daniel,

I see what the problem is. The connection to the HTTP proxy was successfully established,

2021-07-12 15:13:35:985419 [INFO]   [DEBUG] 2021-07-12 14:13:35.985 CURL [140324961773312] (Text)   Trying 86.54.150.xxx:8080...
2021-07-12 15:13:36:184842 [INFO]   [DEBUG] 2021-07-12 14:13:36.184 CURL [140324961773312] (Text) Connected to 86.54.150.xxx (86.54.150.xxx) port 8080 (#0)

but the TLS negotiation failed.

2021-07-12 15:13:36:184935 [INFO]   [DEBUG] 2021-07-12 14:13:36.184 CURL [140324961773312] (Text) ALPN, offering http/1.1
2021-07-12 15:13:36:184991 [INFO]   [DEBUG] 2021-07-12 14:13:36.184 CURL [140324961773312] (Text) Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
2021-07-12 15:13:36:191040 [INFO]   [DEBUG] 2021-07-12 14:13:36.191 CURL [140324961773312] (Text) successfully set certificate verify locations:
2021-07-12 15:13:36:191056 [INFO]   [DEBUG] 2021-07-12 14:13:36.191 CURL [140324961773312] (Text)  CAfile: /etc/pki/tls/certs/ca-bundle.crt
2021-07-12 15:13:36:191063 [INFO]   [DEBUG] 2021-07-12 14:13:36.191 CURL [140324961773312] (Text)  CApath: /etc/ssl/certs
2021-07-12 15:13:36:191251 [INFO]   [DEBUG] 2021-07-12 14:13:36.191 CURL [140324961773312] (Text) TLSv1.2 (OUT), TLS header, Certificate Status (22):
2021-07-12 15:13:36:191273 [INFO]   [DEBUG] 2021-07-12 14:13:36.191 CURL [140324961773312] (SSLDataOut) 5bytes
2021-07-12 15:13:36:191282 [INFO]   [DEBUG] 2021-07-12 14:13:36.191 CURL [140324961773312] (Text) TLSv1.2 (OUT), TLS handshake, Client hello (1):
2021-07-12 15:13:36:191288 [INFO]   [DEBUG] 2021-07-12 14:13:36.191 CURL [140324961773312] (SSLDataOut) 512bytes
2021-07-12 15:13:36:191595 [INFO]   [DEBUG] 2021-07-12 14:13:36.191 CURL [140324961773312] (Text) OpenSSL SSL_connect: SSL_ERROR_SYSCALL in connection to 86.54.150.xxx:8080
2021-07-12 15:13:36:191608 [INFO]   [DEBUG] 2021-07-12 14:13:36.191 CURL [140324961773312] (Text) Closing connection 0

The problem is the connection between the UniMRCP server and the proxy server is supposed to be carried over plain HTTP, whereas HTTPS is attempted by the plugin. This is a regression introduced in one of the latest releases which applies to all the AWS plugins. The URI scheme needs to be made configurable, defaulting to HTTP but not HTTPS, as it is now.

If you can configure your proxy to work over HTTPS, then it would resolve the problem. Otherwise, please wait for further updates. I'll try to provide a patch, when as soon as possible. If the response/resolution times matter, this sort of requests would need to be prioritized and handled through regular support channels but not the community-based discussion group.


--
You received this message because you are subscribed to the Google Groups "UniMRCP" group.
To unsubscribe from this group and stop receiving emails from it, send an email to unimrcp+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/unimrcp/ac86aca2-1d54-4046-bf51-d8105376823en%40googlegroups.com.


--
Arsen Chaloyan
Author of UniMRCP
http://www.unimrcp.org

Daniel Ng

unread,
Aug 26, 2021, 6:57:19 AM8/26/21
to uni...@googlegroups.com
Hi Arsen,

Thank you for spending the time to find the fault - I'll look forward to the patch and also look into the other proxy HTTPS suggestion with the guys who deal with the proxy server on my side.

Kind regards,
Daniel

You received this message because you are subscribed to a topic in the Google Groups "UniMRCP" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/unimrcp/DlND2NTz96U/unsubscribe.
To unsubscribe from this group and all its topics, send an email to unimrcp+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/unimrcp/CAC5Usc%2BbhJhutyufYedJH44FcyZNF3i4WvUPj7cO6aNJCv%3DTeg%40mail.gmail.com.

Arsen Chaloyan

unread,
Aug 30, 2021, 10:24:51 PM8/30/21
to UniMRCP
Hi Daniel,

Please upgrade to the new release published earlier today, which is all you need to do.

For those, who may need to use HTTPS in communication with HTTP proxy, a new configuration attribute proxy-scheme is supposed to be set to "https". The attribute defaults to "http", if not specified.

Thanks for bringing this issue up.

To view this discussion on the web visit https://groups.google.com/d/msgid/unimrcp/CAJjisnzx2ALJL_t5_VEeWkmzuTpkCq%2B1EbXYPM7ZGoZRpK1LeQ%40mail.gmail.com.

Daniel Ng

unread,
Sep 5, 2021, 11:35:07 AM9/5/21
to uni...@googlegroups.com
Hi Arden,
Thank you for letting me know. I’ll try it out. Sorry for the late reply as I was on annual leave
Thanks again 
Regards 
Daniel

Daniel Ng

unread,
Sep 6, 2021, 8:54:24 AM9/6/21
to uni...@googlegroups.com
Hi Arsen,

Thank you - from preliminary testing using the bss1 and lex1 test from umc, I can see that we are successfully communicating with AWS via the proxy now.  The system is successfully retrieving the list of TTS voice name/labels, etc.

It was a case of stopping the service, updating the packages, updating the new configuration files with the required settings and restarting the service before testing with umc.  I've not tested using actual calls yet - that would be the next step.

Thanks again 

Kind regards,
Daniel

Reply all
Reply to author
Forward
0 new messages