SIP Connection Failed with 500 "Internal Server Error"

[iTime]

Hello VG Support,

We are helping one of our clients to setup their SIP trunk to connect to an IVR server with VG, but are having a problem of SIP registration.

We tried various combinations for <VoIP Registration> elements in Config.xml, but still are having an issue.

With the attached Configuration to set a SIP Trunk with Static IP , we get "500 Internal Server Error" (Wireshark log shows this.)

Would you be able to provide any tip/solutions? The SIP Trunk is being built on Cisco Call Manager.

Thank you a lot for your help in advance.

 

VG_SIPErr_2021-06-25.zip

[SupportTeam]

The "Internal Server Error" comes from the remote server with which VoiceGuide/HMP is trying to register (ie: Cisco), so you would need to see Cisco's logs as to why it is issuing that message.

One thing you could try is in VoiceGuide's SIP Registration config, instead of just "5303" being specified as "RegClient" you could try using:

5303@10.1.4.20

[SupportTeam]

Please also enable the HPET on this VoiceGuide system. ktTel trace is currently showing:

016 125143.353  4456         WARN  HPET not enabled. Enable HPET timer and restart Windows. QueryPerformanceFrequency -2147483648MHz (quad=10043069131044072)
017 125143.353  4456         WARN  command to enable HPET: bcdedit /set useplatformclock true

Instructions on enabling the HPET are also available in the "Installing VoiceGuide for VoIP / HMP" help file section.

[iTime]

Thanks for the tips.

Our customer configured the SIP trunk in a way that it is connected to the IVR Server (VG with HMP), but still showing SIP failure with 500 error.

There are a couple of things I'd like to ask you regarding this issue.

1. We ran "bcdedit /set useplatformclock true" several ties and restarted the server, but the log still would show "HPET is NOT enabled." The machine property shows it is "ESXi 6.7 or higher" and the OS is Windows Server 2016. Any suggestion?

2. If you see the log, the call arrives and hit the first module [CheckTaskType] even if Wireshark shows "500 error" with SIP Registration failure, but the process does not proceed to the next module. it just stays there for about 30 seconds until I assume it gets timeout. I am not sure what is causing this error.

3. If you see ktTel log, it shows repeating SIP Register failure message, which will make the file size about 1GB within a minute (So we trimmed the file here for posting purposes). I am not sure how SIP registration failed but the calls could arrive to VG server. And do you think this will still work with VG?

By the way, for your suggestion below, our customer mentioned adding "@IPaddress" caused another error so they did not want to use this setting.

Quote

 

One thing you could try is in VoiceGuide's SIP Registration config, instead of just "5303" being specified as "RegClient" you could try using:

5303@10.1.4.20

 

I have attached the Config file that has the current SIP Registration settings. 

Thank you.

[iTime]

I was not able to upload the zipped log files to the forum ("200 error")

I will try it later.

[iTime]

The log file attached. for the previous post.

Thank you.

VG_ErrLog.zip

[SupportTeam]

If you cannot enable the HPET then suggest speaking with the VMware administrator. Maybe they have used some setting/configuration that prevents the HPET from being enabled?

 

If calls are arriving without the need for SIP Registration then looks like the Cisco is set to just route the calls direct to VoiceGuide IP address, and that is why it is not responding to SIP Register requests. And as the IP address of system is static then this static routing will work, and the SIP Registration config can be removed.

 

Regarding the callflow execution, it looks like the system is not progressing past the first module. Recommend adding more logging into the VBScript ran in that first module to see what is happening. If you still encounter issues with running that script module then please start a new topic on that question.
 

122538.908  14   3   1     1 state call_in_offered : cid=7747@10.1.4.20  dnis=5303@10.1.50.26 |


122538.921  14   3   1     1       answering the call (picking up the line) 8000001


122539.932  20   3   1     1 ev    CallState GCEV_ANSWERED, crn=8000001, iEvent=0 ,256,1,4, s1:, s2:, s3:, build_date: 2020-06-19 21:28:29.06


122540.029  14   3   1     1       RunModule start Run VB Script, [CheckTaskType], vgm=47, previous_vgm=0
122540.029  14   3   1     1 state [CheckTaskType] RunScript |
122540.031  14   3   1     1 t     timer set   30 sec : EV_TIMEOUT_HANGUP
122540.032  14   3   1     1       modvbs QueueUserWorkItem vbScript
122540.032  14   3   1     1       LineEvCallState CONNECTED stats update end
122540.050  27   3   1     1 task  scr Run_VBS vgm=47, file=, RunUsingClearScript=False
122540.050  27   3   1     1 state [CheckTaskType] Run Script vbs, onhold= |
122540.063  27   3   1     1       rv    replace start - not logging - input length is >1000
122540.071  27   3   1     1       rv    dbg   rv_retrieve did not find [UserID]
122540.071  27   3   1     1       rv    dbg   rv_retrieve did not find [AutoNotifyCallID]
122540.071  27   3   1     1       rv    dbg   rv_retrieve did not find [AutoNotifyMoveNotificationCallID]
122540.072  27   3   1     1       rv    dbg   rv_retrieve did not find [IsHiring]
122540.072  27   3   1     1       rv    dbg   rv_retrieve did not find [IsBroadcasting]
122540.072  27   3   1     1       scr   will be waiting. wait=1, calling iModuleIdx=47 (setting iRunWait_VgmIdx to 47)
122540.074  27   3   1     1       moh not set
122540.074  27   3   1     1       scr   Run_VBS_UsingExternalInterpreter
122540.077  27   3   1     1       vbs SaveVbsToFile begin : C:\Program Files (x86)\VoiceGuide\temp\vbs_3_1.vbs
122540.092  29   3   1     1       vbs SaveVbsToFile script saved C:\Program Files (x86)\VoiceGuide\temp\vbs_3_1.vbs
122540.097  27   3   1     1       scr   start - Run_VBS_UsingExternalInterpreter [C:\Program Files (x86)\VoiceGuide\temp\vbs_3_1.vbs]
122540.097  27   3   1     1       scr   external on_hold_file=, iModuleIdx=47
122540.097  27   3   1     1       scr   start - Run_VBS_UsingExternalInterpreter using linelocal_ini_moduleRunScript_Engine: [cscript.exe]
122540.097  27   3   1     1       scr   start - Run_VBS_UsingExternalInterpreter [cscript.exe]["C:\Program Files (x86)\VoiceGuide\temp\vbs_3_1.vbs" //T:30] starttask_approach=simple_create_process
122540.103  27   3   1     1       StartProcessTask run:[cscript.exe] args:["C:\Program Files (x86)\VoiceGuide\temp\vbs_3_1.vbs" //T:30] pref_mode=simple_create_process bHideWindow=True
122540.122  27   3   1     1       StartProcessTask  preferred process start method - simple_create_process : started ok. dwProcessId=7548, hProcess=680, dwThreadId=7600, hThread=684
122540.123  27   3   1     1       Run Script waiting. iRunWait=1 (hProcess=680)
122540.123  27   3   1     1 t     timer set   0.5 sec : EV_TIMEOUT_CHECKONSTATE
122540.123  27   3   1     1       scr   Run_VBS_UsingExternalInterpreter returned


122542.748  23               api   vgServices_CommandLink started
122542.852  23   3   1     1 api   RvSet IsMoveAutoNotify, false
122542.853  23   3   1     1       rv    add   IsMoveAutoNotify|false
122542.981  23               api   vgServices_CommandLink started
122542.985  23               api   vgServices_CommandLink started
122542.986  23               api   vgServices_CommandLink started
122542.987  23               api   vgServices_CommandLink started
122542.989  23               api   vgServices_CommandLink started
122542.990  23               api   vgServices_CommandLink started
122542.992  23               api   vgServices_CommandLink started
122542.994  23               api   vgServices_CommandLink started
122542.996  23               api   vgServices_CommandLink started
122543.000  23               api   vgServices_CommandLink started
122543.005  23               api   vgServices_CommandLink started
122543.017  23               api   vgServices_CommandLink started
122543.038  23               api   vgServices_CommandLink started
122543.081  23               api   vgServices_CommandLink started
122543.236  23               api   vgServices_CommandLink started
122543.713  23               api   vgServices_CommandLink started
122545.366  23               api   vgServices_CommandLink started
122551.392  23               api   vgServices_CommandLink started


122611.091  14   3   1     1       task completed. vgm=47, iRunWait=1, iRunWait_ExeResult_NextVgm=0=[]
122611.092  14   3   1     1       ExeResult_NextVgm has not been set. check for Result file.
122611.093  14   3   1     1       no result file returned from program (VGRUNRESULT_3.TXT).
122611.093  14   3   1     1       LsRunWaitTillFinished LsRunWaitChooseNext boolExeResult=False
122611.095  14   3   1     1       FindNextVgm_Boolean false no paths found
122611.097  14   3   1     1       HangupCall qScr add (WaitTillFinished - next module not specified) crn_in=0, L1=Connected, L2=Running_Normal, lPlayId=0, lRecId=0
122611.097  14   3   1     1       q_scr +     cmdHangupCall 0
122611.098  14   3   1     1       q_scr run   cmdHangupCall 0  action_id=0, crn=0 [0|0|0|0|0][WaitTillFinished - next module not specified|||||] 00:00:00 max:1|0.4992
122611.106  14   3   1     1       HangupCall qScr exec src=WaitTillFinished - next module not specified, opt=, crn_in=0, L1=Connected, L2=Running_Normal, lPlayId=0, lRecId=0
122611.106  14   3   1     1       HangupCall crn_connected=8000001, crn_NewCallArriving=0, crn_CurrentMakeCall=0, crn_InProcessOfReleasing=0
122611.106  14   3   1     1       rv    add   Hangup_Source|WaitTillFinished - next module not specified
122611.106  14   3   1     1       HangupCall sScriptToRunOnHangup=[C:\Program Files (x86)\VoiceGuide\Scripts\IntelliTime\PostHangUp_Hiring.vgs]

 

 

[iTime]

Hello,

Sorry for the late response. It's just follow-up reply to close the case.

Quote

If you cannot enable the HPET then suggest speaking with the VMware administrator. 

Yes, this issue has been resolved after the server got restarted a couple of times; we don't see "HPET..." message anymore in the log file.

Quote

And as the IP address of system is static then this static routing will work, and the SIP Registration config can be removed.

This worked; we have removed <Registration> elements, and VG started working without filling up the log file instantly.

Quote

Recommend adding more logging into the VBScript ran in that first module to see what is happening

Yes, running the first VBscript had revealed that TLS/ODBC did not give proper permissions to the application user. We have resolved it.

 

Thanks for the great support as always.