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: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: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: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: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: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