Solved: Internal Server error

mmartin84 · ‎10-24-2011

I am currently in the process of configuring a new uc320 + Mediatrix 4402, I am able to dial to the system and it goes through to the correct hunt group etc... But when I try to make an outbound call I am receiving "Internal Server Error" on the handset... Please see syslog extract bellow:

v=0
o=- 118650 118650 IN IP4 192.168.1.2
s=-
c=IN IP4 192.168.1.2
t=0 0
m=audio 16408 RTP/AVP 8 0 2 9 18 96 97 98 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:9 G722/8000
a=rtpmap:18 G729a/8000
a=rtpmap:96 G726-40/8000
a=rtpmap:97 G726-24/8000
a=rtpmap:98 G726-16/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:30
a=sendrecv

Oct 25 11:55:47 UC320W user.debug voice:

Oct 25 11:55:47 UC320W user.debug voice: [5]<<192.168.1.1:5060(327)

Oct 25 11:55:47 UC320W user.debug voice: SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bK-6ef2be57
From: Excelsior Gold <sip:0893357770@192.168.1.1>;tag=79f2a6d35d32d988o5;ref=105
To: <sip:0406673789@192.168.1.1>
Call-ID: 3cd9ccef-7eca8a1c@192.168.1.2
CSeq: 101 INVITE
Server: Mediatrix 4402/v2.0.10.185 44XX-MX-D2000-66
Content-Length: 0

Oct 25 11:55:47 UC320W user.debug voice:

Oct 25 11:55:48 UC320W user.debug voice: [5]<<192.168.1.1:5060(357)

Oct 25 11:55:48 UC320W user.debug voice: SIP/2.0 500 Internal Server Error
Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bK-6ef2be57
From: Excelsior Gold <sip:0893357770@192.168.1.1>;tag=79f2a6d35d32d988o5;ref=105
To: <sip:0406673789@192.168.1.1>;tag=2199816069
Call-ID: 3cd9ccef-7eca8a1c@192.168.1.2
CSeq: 101 INVITE
Server: Mediatrix 4402/v2.0.10.185 44XX-MX-D2000-66
Content-Length: 0

Oct 25 11:55:48 UC320W user.debug voice:

Oct 25 11:55:48 UC320W user.debug voice: [5]->192.168.1.1:5060(482)

Oct 25 11:55:48 UC320W user.debug voice: ACK sip:0406673789@192.168.1.1 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bK-6ef2be57
From: Excelsior Gold <sip:0893357770@192.168.1.1>;tag=79f2a6d35d32d988o5;ref=105
To: <sip:0406673789@192.168.1.1>;tag=2199816069
Call-ID: 3cd9ccef-7eca8a1c@192.168.1.2
CSeq: 101 ACK
Max-Forwards: 70
Contact: Excelsior Gold <sip:0893357770@192.168.1.2:5060;ref=0893357770>
User-Agent: Cisco/UC320W-2.1.1(7)
Allow-Events: talk, hold, conference, x-spa-cti
Content-Length: 0

Oct 25 11:55:48 UC320W user.debug voice:

Oct 25 11:55:48 UC320W user.debug voice: ++++ signaling events: 45 509 2b

Oct 25 11:55:48 UC320W user.debug voice: BCC:Failed

Oct 25 11:55:48 UC320W user.debug voice: Voice CDR written

Oct 25 11:55:48 UC320W user.debug voice: ++++ signaling events: 45 509 2b

Oct 25 11:55:48 UC320W user.debug voice: audio restart

Oct 25 11:55:48 UC320W user.debug voice: DLG Terminated 523064

Oct 25 11:55:48 UC320W user.debug voice: Sess Terminated 424ad708

Oct 25 11:55:48 UC320W user.warn kernel: Closing pcm device
Oct 25 11:55:48 UC320W user.warn kernel: PHONE_REC_STOP
Oct 25 11:55:48 UC320W user.warn kernel: PHONE_PLAY_STOP
Oct 25 11:55:48 UC320W user.warn kernel: PHONE_REC_STOP
Oct 25 11:55:48 UC320W user.warn kernel: PHONE_PLAY_STOP
Oct 25 11:55:48 UC320W user.warn kernel: PHONE_REC_STOP
Oct 25 11:55:48 UC320W user.warn kernel: PHONE_PLAY_STOP
Oct 25 11:55:48 UC320W user.warn kernel: PHONE_REC_STOP
Oct 25 11:55:48 UC320W user.warn kernel: PHONE_PLAY_STOP
Oct 25 11:55:48 UC320W user.warn kernel: PHONE_REC_STOP
Oct 25 11:55:48 UC320W user.warn kernel: PHONE_PLAY_STOP
Oct 25 11:55:48 UC320W user.debug voice: aud restarted(50ms)

Oct 25 11:55:48 UC320W user.warn kernel: PHONE_PLAY_START
Oct 25 11:55:48 UC320W user.warn kernel: CPLD indication triggered - Tx/Rx started ok
Oct 25 11:55:48 UC320W user.warn kernel: PHONE_REC_START
Oct 25 11:55:48 UC320W user.warn kernel: PHONE_PLAY_START
Oct 25 11:55:48 UC320W user.warn kernel: PHONE_REC_START
Oct 25 11:55:48 UC320W user.warn kernel: PHONE_PLAY_START
Oct 25 11:55:48 UC320W user.warn kernel: PHONE_REC_START
Oct 25 11:55:48 UC320W user.warn kernel: PHONE_PLAY_START
Oct 25 11:55:48 UC320W user.warn kernel: PHONE_REC_START
Oct 25 11:55:48 UC320W user.warn kernel: PHONE_PLAY_START
Oct 25 11:55:48 UC320W user.warn kernel: PHONE_REC_START
Oct 25 11:55:48 UC320W user.warn kernel: Opening pcm device
Oct 25 11:55:49 UC320W user.debug voice: SAA_DBG:>>>>CheckAADateTime:0

Oct 25 11:55:49 UC320W user.debug voice: localtime is:2011-10-25, 11:55:50

Oct 25 11:55:49 UC320W user.debug voice: start time is:0-0-0

Oct 25 11:55:49 UC320W user.debug voice: end time is:0-0-0

Oct 25 11:55:49 UC320W user.debug voice: SAA_DBG: AA 1 scipt 0

Oct 25 11:55:55 UC320W user.debug voice: TFTPS:<<b01010a:1033 /cfg/reports/spa504G_30e4db809766.xmls

Oct 25 11:55:55 UC320W user.debug voice: TFTPS: Put </home/usb_disk/cfg/reports/spa504G_30e4db809766.xmls>

Oct 25 11:55:55 UC320W user.debug voice: report profile spa504G_30e4db809766.xmls no change

Oct 25 11:55:55 UC320W user.debug voice: report address book spa504G_30e4db809766.xmls no change

Oct 25 11:56:04 UC320W user.debug voice: SAA_DBG:>>>>CheckAADateTime:0

Oct 25 11:56:04 UC320W user.debug voice: localtime is:2011-10-25, 11:56:4

Oct 25 11:56:04 UC320W user.debug voice: start time is:0-0-0

Oct 25 11:56:04 UC320W user.debug voice: end time is:0-0-0

Oct 25 11:56:04 UC320W user.debug voice: SAA_DBG: AA 1 scipt 0

Oct 25 11:56:11 UC320W user.debug kernel: sysevt_comm_sendto: (60, rc)=>
Oct 25 11:56:17 UC320W user.debug kernel: sysevt_comm_sendto: (60, rc)=>
Oct 25 11:56:17 UC320W user.debug kernel: sysevt_comm_sendto: (60, rc)=>
Oct 25 11:56:19 UC320W user.debug voice: SAA_DBG:>>>>CheckAADateTime:0

Oct 25 11:56:19 UC320W user.debug voice: localtime is:2011-10-25, 11:56:19

Oct 25 11:56:19 UC320W user.debug voice: start time is:0-0-0

Oct 25 11:56:19 UC320W user.debug voice: end time is:0-0-0

Oct 25 11:56:19 UC320W user.debug voice: SAA_DBG: AA 1 scipt 0

Oct 25 11:56:20 UC320W user.debug voice: Sess Terminated 424af978

Oct 25 11:56:21 UC320W user.debug voice: CC:Clean Up

Oct 25 11:56:21 UC320W user.debug voice: --- OBJ POOL STAT ---

Oct 25 11:56:21 UC320W user.debug voice: OP:RTPRXB = 96 ( 96 192)
Oct 25 11:56:21 UC320W user.debug voice: OP:RTPREB = 40 ( 40 48)

Oct 25 11:56:21 UC320W user.debug voice: OP:RTPTXB = 64 ( 64 108)
Oct 25 11:56:21 UC320W user.debug voice: OP:TIMEOU = 95 (152 52)

Oct 25 11:56:21 UC320W user.debug voice: OP:SIPCOR = 0 ( 1 32)
Oct 25 11:56:21 UC320W user.debug voice: OP:SIPCTS = 48 ( 48 624)

Oct 25 11:56:21 UC320W user.debug voice: OP:SIPSTS = 36 ( 64 6076)
Oct 25 11:56:21 UC320W user.debug voice: OP:SIPAUS = 8 ( 8 680)

Oct 25 11:56:21 UC320W user.debug voice: OP:SIPDLG = 58 ( 58 164)
Oct 25 11:56:21 UC320W user.debug voice: OP:SIPSES = 40 ( 40 8816)

Oct 25 11:56:21 UC320W user.debug voice: OP:SIPREG = 20 ( 26 468)
Oct 25 11:56:21 UC320W user.debug voice: OP:SIPLIN = 0 ( 15 148)

Oct 25 11:56:21 UC320W user.debug voice: OP:SUBDLG = 0 ( 19 6740)
Oct 25 11:56:21 UC320W user.debug voice: OP:STUNTS = 32 ( 32 68)

Oct 25 11:56:21 UC320W user.debug voice: OP:SIPCTI = 1 ( 9 7428)
Oct 25 11:56:21 UC320W user.debug voice: OP:XMNODE = 1024 (1024 112)

Oct 25 11:56:21 UC320W user.debug voice:

Christopher Edgeworth · ‎10-25-2011

I see on the previous screen that the max calls is 0? Shouldn't that be 2? The call is failing several rows above your highlighted entry on the next screenshot: FindDestination: Call is not allowed.

Chris

View solution in original post

mmartin84 · ‎10-24-2011

Not sure if this is related, but under external trunks, it shows the sip services as not registered....

David Harper · ‎10-24-2011

Can you jump on the GUI for the gateway and grab a couple of screenshots please? In particular, ISDN status and Call Routing Status? It is a bit of a guess at this point, but based on the symptoms, it may be that you only have routing rules set up for the inbound direction and not the outbound.

Cheers,

Dave.

mmartin84 · ‎10-24-2011

mmartin84 · ‎10-24-2011

SR:619505859 give by small business support, though I dont hold out much hope for this option as she kept asking me to send them the running-config... I wish I could see a running config on this thing :/

David Harper · ‎10-24-2011

Well, you can do a config backup from the gateway, and get a nice big XML file. Your mileage may vary when it comes to extracting useful information from it though.

Cheers,

Dave.

David Harper · ‎10-24-2011

Ok, that looks pretty much ok, though I would suggest pointing the sip-default route at the huntgroup since you have that created. Not sure if that will be causing you an issue or not.

Do you have a syslog server available to send logs from the Mediatrix gateway to? If you don't, do a google search for 3CDaemon. It's a freeware tftp/ftp/syslog server for Windows that I have had a lot of success with. Anyway, if you can go to System > Syslog, and enable logging at debug level for ISDN, SIP Endpoint, and Call Routing. If you are really keen, you can also turn on diagnostic traces which will give you a great deal of information, but it might get a little confusing. Anyway, enable logging, make an outbound call, and then send through the logs.

Cheers,

Dave.

mmartin84 · ‎10-24-2011

Attached as image,as the pasted text looked awful. Please let me know if you need any further information?

David Harper · ‎10-24-2011

Ok, looks like the call is being correctly routed to the ISDN interface, but is then falling over. Sorry to keep asking you for stuff, but could you possibly redo the logging with diagnostic traces enabled as well?

Cheers,

Dave.

mmartin84 · ‎10-25-2011

<190>syslog: SipSignaling [0000] Sip signaling logging disabled. 172.16.165.249 25/10 15:00:25.385

<190>syslog: SipSignaling [0001] Sip signaling logs diagnostic traces enabled. 172.16.165.249 25/10 15:00:25.385

<191>syslog: IsdnStackL2State [0002] LAPD if 0: Timer T203 expired in state 7_LINK_CONNECTION_ESTABLISHED 172.16.165.249 25/10 15:00:27.272

<191>syslog: IsdnStackL2Msg [0003] 0) > [Supervisory frame] 172.16.165.249 25/10 15:00:27.272

<191>syslog: IsdnStackL2Msg [0004] 0) > SAPI: 00 C/R: 0 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:27.272

<191>syslog: IsdnStackL2Msg [0005] 0) > N(R): 006 SS: 0 P/F: 1 [ RR Receiver Ready ] 172.16.165.249 25/10 15:00:27.288

<191>syslog: IsdnStackL2Raw [0006] 0) > [ 00 83 01 0d ] 172.16.165.249 25/10 15:00:27.288

<191>syslog: IsdnStackL2State [0007] 0) Starting T200 Timer 172.16.165.249 25/10 15:00:27.288

<191>syslog: IsdnStackL2State [0008] CLapdState::SetState - If 00 changed from 7_LINK_CONNECTION_ESTABLISHED to 8_TIMER_RECOVERY 172.16.165.249 25/10 15:00:27.288

<191>syslog: IsdnStackL1State [0009] PH - Primitive request (PH Data Request) to If (0) 172.16.165.249 25/10 15:00:27.288

<191>syslog: IsdnStackL2State [000A] PH - Primitive request (PH Data Indication) to If (0) 172.16.165.249 25/10 15:00:27.303

<191>syslog: IsdnStackL2Raw [000B] 0) < [ 00 83 01 11 ] 172.16.165.249 25/10 15:00:27.303

<191>syslog: IsdnStackL2Msg [000C] 0) < [Supervisory frame] 172.16.165.249 25/10 15:00:27.303

<191>syslog: IsdnStackL2Msg [000D] 0) < SAPI: 00 C/R: 0 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:27.303

<191>syslog: IsdnStackL2Msg [000E] 0) < N(R): 008 SS: 0 P/F: 1 [RR Receiver Ready] 172.16.165.249 25/10 15:00:27.303

<191>syslog: IsdnStackL2State [000F] 0) ACKing all packets from 8 to (but not including) 8 172.16.165.249 25/10 15:00:27.303

<191>syslog: IsdnStackL2State [0010] 0) Stopping T200 Timer 172.16.165.249 25/10 15:00:27.303

<191>syslog: IsdnStackL2State [0011] 0) Stopping T203 Timer 172.16.165.249 25/10 15:00:27.303

<191>syslog: IsdnStackL2State [0012] 0) Starting T203 Timer 172.16.165.249 25/10 15:00:27.319

<191>syslog: IsdnStackL2State [0013] CLapdState::SetState - If 00 changed from 8_TIMER_RECOVERY to 7_LINK_CONNECTION_ESTABLISHED 172.16.165.249 25/10 15:00:27.319

<191>syslog: IsdnStackL2State [0014] LAPD if 0: Timer T203 expired in state 7_LINK_CONNECTION_ESTABLISHED 172.16.165.249 25/10 15:00:37.303

<191>syslog: IsdnStackL2Msg [0015] 0) > [Supervisory frame] 172.16.165.249 25/10 15:00:37.303

<191>syslog: IsdnStackL2Msg [0016] 0) > SAPI: 00 C/R: 0 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:37.303

<191>syslog: IsdnStackL2Msg [0017] 0) > N(R): 006 SS: 0 P/F: 1 [ RR Receiver Ready ] 172.16.165.249 25/10 15:00:37.303

<191>syslog: IsdnStackL2Raw [0018] 0) > [ 00 83 01 0d ] 172.16.165.249 25/10 15:00:37.303

<191>syslog: IsdnStackL2State [0019] 0) Starting T200 Timer 172.16.165.249 25/10 15:00:37.303

<191>syslog: IsdnStackL2State [001A] CLapdState::SetState - If 00 changed from 7_LINK_CONNECTION_ESTABLISHED to 8_TIMER_RECOVERY 172.16.165.249 25/10 15:00:37.319

<191>syslog: IsdnStackL1State [001B] PH - Primitive request (PH Data Request) to If (0) 172.16.165.249 25/10 15:00:37.319

<191>syslog: IsdnStackL2State [001C] PH - Primitive request (PH Data Indication) to If (0) 172.16.165.249 25/10 15:00:37.334

<191>syslog: IsdnStackL2Raw [001D] 0) < [ 00 83 01 11 ] 172.16.165.249 25/10 15:00:37.334

<191>syslog: IsdnStackL2Msg [001E] 0) < [Supervisory frame] 172.16.165.249 25/10 15:00:37.334

<191>syslog: IsdnStackL2Msg [001F] 0) < SAPI: 00 C/R: 0 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:37.334

<191>syslog: IsdnStackL2Msg [0020] 0) < N(R): 008 SS: 0 P/F: 1 [RR Receiver Ready] 172.16.165.249 25/10 15:00:37.334

<191>syslog: IsdnStackL2State [0021] 0) ACKing all packets from 8 to (but not including) 8 172.16.165.249 25/10 15:00:37.350

<191>syslog: IsdnStackL2State [0022] 0) Stopping T200 Timer 172.16.165.249 25/10 15:00:37.350

<191>syslog: IsdnStackL2State [0023] 0) Stopping T203 Timer 172.16.165.249 25/10 15:00:37.350

<191>syslog: IsdnStackL2State [0024] 0) Starting T203 Timer 172.16.165.249 25/10 15:00:37.365

<191>syslog: IsdnStackL2State [0025] CLapdState::SetState - If 00 changed from 8_TIMER_RECOVERY to 7_LINK_CONNECTION_ESTABLISHED 172.16.165.249 25/10 15:00:37.365

<191>syslog: SipSignaling [0026] < [192.168.1.1:5060] Received SIP packet from: 192.168.1.2:5060 172.16.165.249 25/10 15:00:39.206

<191>syslog: SipSignaling [0027] < INVITE sip:0406673789@192.168.1.1 SIP/2.0 172.16.165.249 25/10 15:00:39.206

<191>syslog: SipSignaling [0028] < Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bK-724e226a 172.16.165.249 25/10 15:00:39.222

<191>syslog: SipSignaling [0029] < From: Excelsior Gold <0893357770>;tag=6c52992e7a134e69o5;ref=105 172.16.165.249 25/10 15:00:39.222

<191>syslog: SipSignaling [002A] < To: <0406673789> 172.16.165.249 25/10 15:00:39.237

<191>syslog: SipSignaling [002B] < Remote-Party-ID: Excelsior Gold <0893357770>;screen=yes;party=calling 172.16.165.249 25/10 15:00:39.237

<191>syslog: SipSignaling [002C] < Call-ID:

25da2052-377ad195@192.168.1.2

172.16.165.249 25/10 15:00:39.253

<191>syslog: SipSignaling [002D] < CSeq: 101 INVITE 172.16.165.249 25/10 15:00:39.253

<191>syslog: SipSignaling [002E] < Max-Forwards: 70 172.16.165.249 25/10 15:00:39.253

<191>syslog: SipSignaling [002F] < Contact: Excelsior Gold <0893357770> 172.16.165.249 25/10 15:00:39.269

<191>syslog: SipSignaling [0030] < Expires: 240 172.16.165.249 25/10 15:00:39.269

<191>syslog: SipSignaling [0031] < User-Agent: Cisco/UC320W-2.1.1(7) 172.16.165.249 25/10 15:00:39.284

<191>syslog: SipSignaling [0032] < Allow-Events: talk, hold, conference, x-spa-cti 172.16.165.249 25/10 15:00:39.284

<191>syslog: SipSignaling [0033] < Content-Length: 395 172.16.165.249 25/10 15:00:39.284

<191>syslog: SipSignaling [0034] < Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER 172.16.165.249 25/10 15:00:39.284

<191>syslog: SipSignaling [0035] < Supported: x-sipura, replaces 172.16.165.249 25/10 15:00:39.300

<191>syslog: SipSignaling [0036] < Content-Type: application/sdp 172.16.165.249 25/10 15:00:39.300

<191>syslog: SipSignaling [0037] < 172.16.165.249 25/10 15:00:39.300

<191>syslog: SipSignaling [0038] < v=0 172.16.165.249 25/10 15:00:39.300

<191>syslog: SipSignaling [0039] < o=- 1215247 1215247 IN IP4 192.168.1.2 172.16.165.249 25/10 15:00:39.300

<191>syslog: SipSignaling [003A] < s=- 172.16.165.249 25/10 15:00:39.315

<191>syslog: SipSignaling [003B] < c=IN IP4 192.168.1.2 172.16.165.249 25/10 15:00:39.315

<191>syslog: SipSignaling [003C] < t=0 0 172.16.165.249 25/10 15:00:39.315

<191>syslog: SipSignaling [003D] < m=audio 16468 RTP/AVP 8 0 2 9 18 96 97 98 101 172.16.165.249 25/10 15:00:39.315

<191>syslog: SipSignaling [003E] < a=rtpmap:8 PCMA/8000 172.16.165.249 25/10 15:00:39.315

<191>syslog: SipSignaling [003F] < a=rtpmap:0 PCMU/8000 172.16.165.249 25/10 15:00:39.331

<191>syslog: SipSignaling [0040] < a=rtpmap:2 G726-32/8000 172.16.165.249 25/10 15:00:39.331

<191>syslog: SipSignaling [0041] < a=rtpmap:9 G722/8000 172.16.165.249 25/10 15:00:39.331

<191>syslog: SipSignaling [0042] < a=rtpmap:18 G729a/8000 172.16.165.249 25/10 15:00:39.331

<191>syslog: SipSignaling [0043] < a=rtpmap:96 G726-40/8000 172.16.165.249 25/10 15:00:39.331

<191>syslog: SipSignaling [0044] < a=rtpmap:97 G726-24/8000 172.16.165.249 25/10 15:00:39.347

<191>syslog: SipSignaling [0045] < a=rtpmap:98 G726-16/8000 172.16.165.249 25/10 15:00:39.347

<191>syslog: SipSignaling [0046] < a=rtpmap:101 telephone-event/8000 172.16.165.249 25/10 15:00:39.347

<191>syslog: SipSignaling [0047] < a=fmtp:101 0-15 172.16.165.249 25/10 15:00:39.347

<191>syslog: SipSignaling [0048] < a=ptime:30 172.16.165.249 25/10 15:00:39.347

<191>syslog: SipSignaling [0049] < a=sendrecv 172.16.165.249 25/10 15:00:39.347

<191>syslog: CallTable [004A] CreateCall - Interface sip-default create call 52-53. 172.16.165.249 25/10 15:00:39.347

<191>syslog: SipEngine [004B] [default] L0 N0 C52 Context 0x0127B8D0 created. 172.16.165.249 25/10 15:00:39.362

<191>syslog: SipEngine [004C] [default] L0 N0 C52 User

0406673789@192.168.1.1

was INVITED by

0893357770@192.168.1.1

. 172.16.165.249 25/10 15:00:39.362

<191>syslog: CallManager [004D] C52 - CallSetupA 172.16.165.249 25/10 15:00:39.362

<191>syslog: CallTable [004E] AddRefCall - Interface cm-CM try to add reference to call 52. 172.16.165.249 25/10 15:00:39.362

<191>syslog: CallTable [004F] AddRefCall - Interface cm-CM add reference to call 52. 172.16.165.249 25/10 15:00:39.362

<191>syslog: CallManager [0050] C52-53 - FindDestination: Forward call to the CallRouter 172.16.165.249 25/10 15:00:39.362

<191>syslog: CallRouter [0051] Call 52-53 enter in callrouter: 172.16.165.249 25/10 15:00:39.362

<191>syslog: CallRouter [0052] Src=[CID:52 IID:sip-default CP:date=01.01.2000 UTC,time=03:07:57 UTC,e164=0893357770,name=Excelsior Gold,host=192.168.1.2,uri=sip:0893357770@192.168.1.1,domain=,localip=192.168.1.1,hostname=,sipfrom=Excelsior Gold <08933 172.16.165.249="" 25="">

<191>syslog: CallRouter [0053] Dst1/1=[CID:53 IID:- CP:e164=0406673789,host=192.168.1.1,uri=sip:0406673789@192.168.1.1,usr=0406673789,] 172.16.165.249 25/10 15:00:39.362

<191>syslog: CallRouteTable [0054] Handle Call 52-53. 172.16.165.249 25/10 15:00:39.362

<191>syslog: CallRouteTable [0055] Source interface sip-default matches source criteria sip-default 172.16.165.249 25/10 15:00:39.362

<191>syslog: CallRouteTable [0056] Match default criteria. 172.16.165.249 25/10 15:00:39.378

<191>syslog: CallRouteTable [0057] Insert new destination isdn-Bri1. 172.16.165.249 25/10 15:00:39.378

<191>syslog: CallRouter [0058] Call 52-53 exit from callrouter: 172.16.165.249 25/10 15:00:39.378

<191>syslog: CallRouter [0059] Src=[CID:52 IID:sip-default CP:date=01.01.2000 UTC,time=03:07:57 UTC,e164=0893357770,name=Excelsior Gold,host=192.168.1.2,uri=sip:0893357770@192.168.1.1,domain=,localip=192.168.1.1,hostname=,sipfrom=Excelsior Gold <08933 172.16.165.249="" 25="">

<191>syslog: CallRouter [005A] Dst1/2=[CID:53 IID:- CP:e164=0406673789,host=192.168.1.1,uri=sip:0406673789@192.168.1.1,usr=0406673789,] 172.16.165.249 25/10 15:00:39.378

<191>syslog: CallRouter [005B] Dst2/2=[CID:54 IID:isdn-Bri1 CP:e164=0406673789,host=192.168.1.1,uri=sip:0406673789@192.168.1.1,usr=0406673789,] 172.16.165.249 25/10 15:00:39.378

<191>syslog: CallTable [005C] UseNextDestination - Call 52-54 use new destination isdn-Bri1. 172.16.165.249 25/10 15:00:39.378

<015>SipEp: 1400-SIP Endpoint: 110-New incoming call 52 from

0893357770@192.168.1.1

to

0406673789@192.168.1.1

. 172.16.165.249 25/10 15:00:39.378

<191>syslog: CallManager [005D] C52-54 - FindDestination: Call is allowed 172.16.165.249 25/10 15:00:39.378

<191>syslog: CallManager [005E] C54 - Send CallSetupA 172.16.165.249 25/10 15:00:39.378

<191>syslog: LineEngine [005F] EP1 Reserved. 172.16.165.249 25/10 15:00:39.378

<187>syslog: RTP [0060] CRtpEngine::GetRtpFields() - Find failed - AID1, CID0x0000002D 172.16.165.249 25/10 15:00:39.378

<191>syslog: LineEngine [0061] EP1 LowLevel report channel open : id=1 172.16.165.249 25/10 15:00:39.393

<191>syslog: EndPoint [0062] EP1: Line-side companding successully set to uLaw. 172.16.165.249 25/10 15:00:39.393

<191>syslog: EndPoint [0063] EP1 Jitter Buffer playout_type(Adapt Silence) vp_min_delay(30) vp_nom_delay(60) vp_max_delay(90) concealment(G711A) 172.16.165.249 25/10 15:00:39.393

<191>syslog: EndPoint [0064] EP1 EnterPreVoiceMode: Going in PreVoice mode 172.16.165.249 25/10 15:00:39.393

<191>syslog: EndPoint [0065] EP1 ModifyDigitDetectionConfig: Modify digit detection configuration 172.16.165.249 25/10 15:00:39.425

<191>syslog: CommandDigitInt [0066] L1 N1 - Change state from "FINAL" to "FINAL" 172.16.165.249 25/10 15:00:39.425

<191>syslog: LineEngine [0067] EP1 StopTone 172.16.165.249 25/10 15:00:39.440

<191>syslog: IsdnInterface [0068] L1 B1 - Change state from "Idle" to "Idle" 172.16.165.249 25/10 15:00:39.440

<191>syslog: CallTable [0069] AddRefCall - Interface isdn-Bri1 try to add reference to call 54. 172.16.165.249 25/10 15:00:39.440

<191>syslog: CallTable [006A] AddRefCall - Interface isdn-Bri1 add reference to call 54. 172.16.165.249 25/10 15:00:39.440

<191>syslog: IsdnInterface [006B] L1 B1 - CallSetupA received for call ID 54 accepted. 172.16.165.249 25/10 15:00:39.456

<190>syslog: IsdnInterface [006C] L1 B1 - Multiple Cause IE unsupported, sending only primary Bearer Capability. 172.16.165.249 25/10 15:00:39.456

<191>syslog: IsdnInterface [006D] L1 B1 - No PI received from CM, using default (allowed). 172.16.165.249 25/10 15:00:39.456

<191>syslog: IsdnInterface [006E] L1 B1 - No TON received from CM for caller, using default. 172.16.165.249 25/10 15:00:39.456

<190>syslog: IsdnInterface [006F] L1 B1 - Caller's TON is different from National and International: Calling Number IA5 digits may be dropped by the Network! 172.16.165.249 25/10 15:00:39.471

<191>syslog: IsdnInterface [0070] L1 B1 - No NPI received from CM, using default. 172.16.165.249 25/10 15:00:39.471

<191>syslog: IsdnInterface [0071] L1 B1 - No SI received from CM, using default. 172.16.165.249 25/10 15:00:39.471

<191>syslog: IsdnInterface [0072] L1 B1 - No TON received from CM for called user, using default. 172.16.165.249 25/10 15:00:39.471

<191>syslog: IsdnInterface [0073] L1 B1 - No NPI received from CM for called user, using default. 172.16.165.249 25/10 15:00:39.471

<191>syslog: EndPoint [0074] EP1: Line-side companding successully set to aLaw. 172.16.165.249 25/10 15:00:39.487

<191>syslog: IsdnInterface [0075] L1 B1 - Change state from "Idle" to "CallSetup" 172.16.165.249 25/10 15:00:39.487

<191>syslog: IsdnStackL3State [0076] CIsdnState::DispatchCCbMsg - Primitive request (53) to call 0xf (OutBound) 172.16.165.249 25/10 15:00:39.487

<191>syslog: IsdnStackL3Msg [0077] 0 > Call 15-Outbound TEI 65 SEND Setup (5) 172.16.165.249 25/10 15:00:39.487

<191>syslog: IsdnStackL3Msg [0078] 0 > IE Bearer Capability [Coding: CCITT (0) Info transfer cap: 3.1 kHz audio (16) Trans mode/rate: Circuit (0) 64 kbps (16) User info Layer 1/2/3: g.711 a-law (3) Unused (-1) Unused (-1) In Band Neg Pos: 1] 172.16.165.249 25/10 15:00:39.487

<191>syslog: IsdnStackL3Msg [0079] 0 > IE Channel Id 1/2 [IntID: Implicit Basic (0) 0 Preferred DChan: Is not D channel Pref: Preferred] 172.16.165.249 25/10 15:00:39.487

<191>syslog: IsdnStackL3Msg [007A] 0 > IE Channel Id 2/2 [Chan Sel: 0] 172.16.165.249 25/10 15:00:39.503

<191>syslog: IsdnStackL3Msg [007B] 0 > IE Progress Indicator [Coding standard: CCITT (0) Location: User (0) Description: Call is not end-to-end (1)] 172.16.165.249 25/10 15:00:39.503

<191>syslog: IsdnStackL3Msg [007C] 0 > IE Calling Party Number [TON: Unknown (0) NPI: Unknown (0) PI: Presentation allowed (0) SI: User provided, not screened (0) '0893357770'] 172.16.165.249 25/10 15:00:39.503

<191>syslog: IsdnStackL3Msg [007D] 0 > IE Called Party Number [TON: Unknown (0) NPI: Unknown (0) '0406673789'] 172.16.165.249 25/10 15:00:39.503

<191>syslog: IsdnStackL3Msg [007E] 0 > IE User User [Discriminator: IA5 Characters (4) Info: 'Excelsior Gold']. 172.16.165.249 25/10 15:00:39.503

<191>syslog: IsdnStackL3Msg [007F] 0 > IE Sending Complete 172.16.165.249 25/10 15:00:39.503

<191>syslog: IsdnStackL3State [0080] ISDN if 0, Call 15-Outbound: Starting T303 Timer in state U0_NULL_STATE. 172.16.165.249 25/10 15:00:39.503

<191>syslog: IsdnStackL3State [0081] Call 0xf changed state from U0_NULL_STATE to U1_CALL_INITIATED 172.16.165.249 25/10 15:00:39.503

<191>syslog: IsdnStackL2State [0082] DL-Primitive request (DL Data Request) to If (0) 172.16.165.249 25/10 15:00:39.518

<191>syslog: IsdnStackL2State [0083] 0) Stopping T203 Timer 172.16.165.249 25/10 15:00:39.518

<191>syslog: IsdnStackL2State [0084] 0) Starting T200 Timer 172.16.165.249 25/10 15:00:39.518

<191>syslog: IsdnStackL2Msg [0085] 0) > [Informational frame] 172.16.165.249 25/10 15:00:39.518

<191>syslog: IsdnStackL2Msg [0086] 0) > SAPI: 00 C/R: 0 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:39.518

<191>syslog: IsdnStackL2Msg [0087] 0) > N(R): 006 N(S): 008 P/F: 0 [ Informational ] 172.16.165.249 25/10 15:00:39.518

<191>syslog: IsdnStackL2Raw [0088] 0) > [ 00 83 10 0c 08 01 0f 05 04 03 90 90 a3 18 01 81 1e 02 80 81 6c 0c 00 80 30 38 39 33 33 35 37 37 37 30 70 0b 80 30 34 30 36 36 37 33 37 38 39 7e 0f 04 45 78 63 65 6c 73 69 6f 72 20 47 6f 6c 64 a1 ] 172.16.165.249 25/10 15:00:39.518

<191>syslog: IsdnStackL1State [0089] PH - Primitive request (PH Data Request) to If (0) 172.16.165.249 25/10 15:00:39.518

<191>syslog: Admin [008A] Bri1 usage state is now Busy. 172.16.165.249 25/10 15:00:39.534

<191>syslog: Admin [008B] Slot0 usage state is now Busy. 172.16.165.249 25/10 15:00:39.534

<191>syslog: Admin [008C] Unit usage state is now Busy. 172.16.165.249 25/10 15:00:39.534

<014>Isdn: 1850-Integrated Services Digital Network: 40-Bri1, B-channel 1: State changed to used. 172.16.165.249 25/10 15:00:39.534

<191>syslog: IsdnStackL2State [008D] PH - Primitive request (PH Data Indication) to If (0) 172.16.165.249 25/10 15:00:39.534

<191>syslog: IsdnStackL2Raw [008E] 0) < [ 00 83 01 12 ] 172.16.165.249 25/10 15:00:39.534

<191>syslog: IsdnStackL2Msg [008F] 0) < [Supervisory frame] 172.16.165.249 25/10 15:00:39.534

<191>syslog: IsdnStackL2Msg [0090] 0) < SAPI: 00 C/R: 0 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:39.534

<191>syslog: IsdnStackL2Msg [0091] 0) < N(R): 009 SS: 0 P/F: 0 [RR Receiver Ready] 172.16.165.249 25/10 15:00:39.534

<191>syslog: IsdnStackL2State [0092] 0) ACKing all packets from 8 to (but not including) 9 172.16.165.249 25/10 15:00:39.534

<191>syslog: IsdnStackL2State [0093] 0) Stopping T200 Timer 172.16.165.249 25/10 15:00:39.534

<191>syslog: IsdnStackL2State [0094] 0) Stopping T203 Timer 172.16.165.249 25/10 15:00:39.534

<191>syslog: IsdnStackL2State [0095] 0) Starting T203 Timer 172.16.165.249 25/10 15:00:39.534

<191>syslog: SipSignaling [0096] > [192.168.1.1:5060] Sending SIP packet to: 192.168.1.2:5060 172.16.165.249 25/10 15:00:39.549

<191>syslog: SipSignaling [0097] > SIP/2.0 100 Trying 172.16.165.249 25/10 15:00:39.549

<191>syslog: SipSignaling [0098] > Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bK-724e226a 172.16.165.249 25/10 15:00:39.549

<191>syslog: SipSignaling [0099] > From: Excelsior Gold <0893357770>;tag=6c52992e7a134e69o5;ref=105 172.16.165.249 25/10 15:00:39.549

<191>syslog: SipSignaling [009A] > To: <0406673789> 172.16.165.249 25/10 15:00:39.549

<191>syslog: SipSignaling [009B] > Call-ID:

25da2052-377ad195@192.168.1.2

172.16.165.249 25/10 15:00:39.549

<191>syslog: SipSignaling [009C] > CSeq: 101 INVITE 172.16.165.249 25/10 15:00:39.549

<191>syslog: SipSignaling [009D] > Server: Mediatrix 4402/v2.0.10.185 44XX-MX-D2000-66 172.16.165.249 25/10 15:00:39.549

<191>syslog: SipSignaling [009E] > Content-Length: 0 172.16.165.249 25/10 15:00:39.549

<191>syslog: SipSignaling [009F] > 172.16.165.249 25/10 15:00:39.549

<191>syslog: IsdnStackL2State [00A0] PH - Primitive request (PH Data Indication) to If (0) 172.16.165.249 25/10 15:00:39.846

<191>syslog: IsdnStackL2Raw [00A1] 0) < [ 02 83 0c 12 08 01 8f 7d 08 03 82 ab 7e 14 01 01 ] 172.16.165.249 25/10 15:00:39.861

<191>syslog: IsdnStackL2Msg [00A2] 0) < [Informational frame] 172.16.165.249 25/10 15:00:39.861

<191>syslog: IsdnStackL2Msg [00A3] 0) < SAPI: 00 C/R: 1 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:39.877

<191>syslog: IsdnStackL2Msg [00A4] 0) < N(R): 009 N(S): 006 P/F: 0 172.16.165.249 25/10 15:00:39.877

<191>syslog: IsdnStackL2Msg [00A5] 0) < VR: 006 VS: 009 VA: 009 172.16.165.249 25/10 15:00:39.893

<191>syslog: IsdnStackL2Msg [00A6] 0) > [Supervisory frame] 172.16.165.249 25/10 15:00:39.893

<191>syslog: IsdnStackL2Msg [00A7] 0) > SAPI: 00 C/R: 1 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:39.908

<191>syslog: IsdnStackL2Msg [00A8] 0) > N(R): 007 SS: 0 P/F: 0 [ RR Receiver Ready ] 172.16.165.249 25/10 15:00:39.908

<191>syslog: IsdnStackL2Raw [00A9] 0) > [ 02 83 01 0e ] 172.16.165.249 25/10 15:00:39.924

<191>syslog: IsdnStackL2State [00AA] 0) ACKing all packets from 9 to (but not including) 9 172.16.165.249 25/10 15:00:39.924

<191>syslog: IsdnStackL2State [00AB] 0) Stopping T200 Timer 172.16.165.249 25/10 15:00:39.924

<191>syslog: IsdnStackL2State [00AC] 0) Stopping T203 Timer 172.16.165.249 25/10 15:00:39.939

<191>syslog: IsdnStackL2State [00AD] 0) Starting T203 Timer 172.16.165.249 25/10 15:00:39.939

<191>syslog: IsdnStackL3Msg [00AE] DL - Primitive request (DL Data Indication) to If (0) 172.16.165.249 25/10 15:00:39.939

<191>syslog: IsdnStackL3Msg [00AF] 0 < Call 15-Outbound TEI 65 Unicast RECV Status (125) 172.16.165.249 25/10 15:00:39.939

<191>syslog: IsdnStackL3Msg [00B0] 0 < IE Cause [Coding: CCITT (0) Location: Public network serving local user (2) Cause: Access information discarded (43)] 172.16.165.249 25/10 15:00:39.955

<191>syslog: IsdnStackL3Msg [00B1] 0 < IE Call State [Coding standard: CCITT (0) State value: 1_CALL_INITIATED (1)] 172.16.165.249 25/10 15:00:39.955

<191>syslog: IsdnStackL3State [00B2] CIsdnState::DispatchIsdnMsg - Status message dispatched to call 15 (OutBound) 172.16.165.249 25/10 15:00:39.955

<191>syslog: IsdnStackL1State [00B3] PH - Primitive request (PH Data Request) to If (0) 172.16.165.249 25/10 15:00:39.955

<191>syslog: IsdnInterface [00B4] L1 B1 - Change state from "CallSetup" to "AwaitReleasing" 172.16.165.249 25/10 15:00:39.955

<191>syslog: CallManager [00B5] C54 - CallReleaseA(43, -1) 172.16.165.249 25/10 15:00:39.971

<191>syslog: CallTable [00B6] ReleaseCall - Interface cm-CM try to release call 52. 172.16.165.249 25/10 15:00:39.971

<191>syslog: CallTable [00B7] ReleaseCall - Interface cm-CM release call 52. 172.16.165.249 25/10 15:00:39.971

<191>syslog: CallManager [00B8] C52 - Send CallReleaseA(43) 172.16.165.249 25/10 15:00:39.971

<191>syslog: IsdnStackL3State [00B9] CIsdnState::DispatchCCbMsg - Primitive request (35) to call 0xf (OutBound) 172.16.165.249 25/10 15:00:39.971

<191>syslog: IsdnStackL3State [00BA] ISDN if 0, Call 15-Outbound: Stopping T303 Timer in state U1_CALL_INITIATED. 172.16.165.249 25/10 15:00:39.986

<191>syslog: IsdnStackL3Msg [00BB] 0 > Call 15-Outbound TEI 65 SEND Disconnect (69) 172.16.165.249 25/10 15:00:39.986

<191>syslog: IsdnStackL3Msg [00BC] 0 > IE Cause [Coding: CCITT (0) Location: User (0) Cause: Access information discarded (43)] 172.16.165.249 25/10 15:00:39.986

<191>syslog: IsdnStackL3State [00BD] ISDN if 0, Call 15-Outbound: Starting T305 Timer in state U1_CALL_INITIATED. 172.16.165.249 25/10 15:00:39.986

<191>syslog: IsdnStackL3State [00BE] Call 0xf changed state from U1_CALL_INITIATED to U11_DISCONNECT_REQUEST 172.16.165.249 25/10 15:00:39.986

<191>syslog: IsdnStackL2State [00BF] DL-Primitive request (DL Data Request) to If (0) 172.16.165.249 25/10 15:00:39.986

<191>syslog: SipEngine [00C0] [default] C52 CallReleaseA(43) 172.16.165.249 25/10 15:00:39.986

<191>syslog: IsdnStackL2State [00C1] 0) Stopping T203 Timer 172.16.165.249 25/10 15:00:39.986

<191>syslog: IsdnStackL2State [00C2] 0) Starting T200 Timer 172.16.165.249 25/10 15:00:40.002

<191>syslog: IsdnStackL2Msg [00C3] 0) > [Informational frame] 172.16.165.249 25/10 15:00:40.002

<191>syslog: IsdnStackL2Msg [00C4] 0) > SAPI: 00 C/R: 0 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:40.002

<191>syslog: IsdnStackL2Msg [00C5] 0) > N(R): 007 N(S): 009 P/F: 0 [ Informational ] 172.16.165.249 25/10 15:00:40.002

<191>syslog: IsdnStackL2Raw [00C6] 0) > [ 00 83 12 0e 08 01 0f 45 08 02 80 ab ] 172.16.165.249 25/10 15:00:40.002

<191>syslog: IsdnStackL1State [00C7] PH - Primitive request (PH Data Request) to If (0) 172.16.165.249 25/10 15:00:40.002

<191>syslog: IsdnStackL2State [00C8] PH - Primitive request (PH Data Indication) to If (0) 172.16.165.249 25/10 15:00:40.002

<191>syslog: IsdnStackL2Raw [00C9] 0) < [ 02 83 0e 12 08 01 8f 02 18 01 89 ] 172.16.165.249 25/10 15:00:40.002

<191>syslog: IsdnStackL2Msg [00CA] 0) < [Informational frame] 172.16.165.249 25/10 15:00:40.002

<191>syslog: IsdnStackL2Msg [00CB] 0) < SAPI: 00 C/R: 1 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:40.002

<191>syslog: IsdnStackL2Msg [00CC] 0) < N(R): 009 N(S): 007 P/F: 0 172.16.165.249 25/10 15:00:40.002

<191>syslog: IsdnStackL2Msg [00CD] 0) < VR: 007 VS: 010 VA: 009 172.16.165.249 25/10 15:00:40.017

<191>syslog: IsdnStackL2Msg [00CE] 0) > [Supervisory frame] 172.16.165.249 25/10 15:00:40.017

<191>syslog: IsdnStackL2Msg [00CF] 0) > SAPI: 00 C/R: 1 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:40.017

<191>syslog: IsdnStackL2Msg [00D0] 0) > N(R): 008 SS: 0 P/F: 0 [ RR Receiver Ready ] 172.16.165.249 25/10 15:00:40.017

<191>syslog: IsdnStackL2Raw [00D1] 0) > [ 02 83 01 10 ] 172.16.165.249 25/10 15:00:40.017

<191>syslog: IsdnStackL3Msg [00D2] DL - Primitive request (DL Data Indication) to If (0) 172.16.165.249 25/10 15:00:40.017

<191>syslog: IsdnStackL3Msg [00D3] 0 < Call 15-Outbound TEI 65 Unicast RECV Call Proceeding (2) 172.16.165.249 25/10 15:00:40.017

<191>syslog: IsdnStackL3Msg [00D4] 0 < IE Channel Id 1/2 [IntID: Implicit Basic (0) 0 Preferred DChan: Is not D channel Pref: Exclusive] 172.16.165.249 25/10 15:00:40.017

<191>syslog: IsdnStackL3Msg [00D5] 0 < IE Channel Id 2/2 [Chan Sel: 0] 172.16.165.249 25/10 15:00:40.017

<191>syslog: IsdnStackL3State [00D6] CIsdnState::DispatchIsdnMsg - Call Proceeding message dispatched to call 15 (OutBound) 172.16.165.249 25/10 15:00:40.017

<187>syslog: IsdnStackL3State [00D7] ISDN if 0: Message Incompatible HandleCallProceeding in state U11_DISCONNECT_REQUEST 172.16.165.249 25/10 15:00:40.017

<191>syslog: IsdnStackL3Msg [00D8] 0 > Call 15-Outbound TEI 65 SEND Status (125) 172.16.165.249 25/10 15:00:40.017

<191>syslog: IsdnStackL3Msg [00D9] 0 > IE Cause [Coding: CCITT (0) Location: User (0) Cause: Message not compatible with call state (101)] 172.16.165.249 25/10 15:00:40.017

<191>syslog: IsdnStackL3Msg [00DA] 0 > IE Call State [Coding standard: CCITT (0) State value: 11_DISCONNECT_REQ (11)] 172.16.165.249 25/10 15:00:40.017

<191>syslog: IsdnStackL1State [00DB] PH - Primitive request (PH Data Request) to If (0) 172.16.165.249 25/10 15:00:40.033

<191>syslog: IsdnStackL2State [00DC] DL-Primitive request (DL Data Request) to If (0) 172.16.165.249 25/10 15:00:40.033

<191>syslog: IsdnStackL2Msg [00DD] 0) > [Informational frame] 172.16.165.249 25/10 15:00:40.033

<191>syslog: IsdnStackL2Msg [00DE] 0) > SAPI: 00 C/R: 0 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:40.033

<191>syslog: IsdnStackL2Msg [00DF] 0) > N(R): 008 N(S): 010 P/F: 0 [ Informational ] 172.16.165.249 25/10 15:00:40.033

<191>syslog: IsdnStackL2Raw [00E0] 0) > [ 00 83 14 10 08 01 0f 7d 08 02 80 e5 14 01 0b ] 172.16.165.249 25/10 15:00:40.033

<191>syslog: IsdnStackL1State [00E1] PH - Primitive request (PH Data Request) to If (0) 172.16.165.249 25/10 15:00:40.033

<191>syslog: IsdnStackL2State [00E2] PH - Primitive request (PH Data Indication) to If (0) 172.16.165.249 25/10 15:00:40.033

<191>syslog: IsdnStackL2Raw [00E3] 0) < [ 00 83 01 14 ] 172.16.165.249 25/10 15:00:40.033

<191>syslog: IsdnStackL2Msg [00E4] 0) < [Supervisory frame] 172.16.165.249 25/10 15:00:40.033

<191>syslog: IsdnStackL2Msg [00E5] 0) < SAPI: 00 C/R: 0 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:40.033

<191>syslog: IsdnStackL2Msg [00E6] 0) < N(R): 010 SS: 0 P/F: 0 [RR Receiver Ready] 172.16.165.249 25/10 15:00:40.033

<191>syslog: IsdnStackL2State [00E7] 0) ACKing all packets from 9 to (but not including) 10 172.16.165.249 25/10 15:00:40.033

<191>syslog: IsdnStackL2State [00E8] 0) Stopping T200 Timer 172.16.165.249 25/10 15:00:40.049

<191>syslog: IsdnStackL2State [00E9] 0) Starting T200 Timer 172.16.165.249 25/10 15:00:40.049

<191>syslog: SipEngine [00EA] [default] L0 N0 C52 Received invitation refused. Reason: 43. SIP code: 500 172.16.165.249 25/10 15:00:40.049

<191>syslog: SipEngine [00EB] [default] L0 N0 C52 Send error response 500 (). 172.16.165.249 25/10 15:00:40.049

<191>syslog: SipEngine [00EC] [default] L0 N0 C52 CCallCx::CmSendCallRelease cannot send a call release with cause 16 since the call is already released. 172.16.165.249 25/10 15:00:40.049

<190>syslog: SipEngine [00ED] [default] L0 N0 C52 Call state change from IDLE to TERMINATED. 172.16.165.249 25/10 15:00:40.049

<191>syslog: SipEngine [00EE] [default] L0 N0 C52 Releasing call context 0x0127B8D0. 172.16.165.249 25/10 15:00:40.049

<191>syslog: CallTable [00EF] ReleaseCall - Interface sip-default try to release call 52. 172.16.165.249 25/10 15:00:40.049

<191>syslog: CallTable [00F0] ReleaseCall - Interface sip-default release call 52. 172.16.165.249 25/10 15:00:40.049

<191>syslog: SipSignaling [00F1] > [192.168.1.1:5060] Sending SIP packet to: 192.168.1.2:5060 172.16.165.249 25/10 15:00:40.049

<191>syslog: SipSignaling [00F2] > SIP/2.0 500 Internal Server Error 172.16.165.249 25/10 15:00:40.049

<191>syslog: SipSignaling [00F3] > Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bK-724e226a 172.16.165.249 25/10 15:00:40.049

<191>syslog: SipSignaling [00F4] > From: Excelsior Gold <0893357770>;tag=6c52992e7a134e69o5;ref=105 172.16.165.249 25/10 15:00:40.049

<191>syslog: SipSignaling [00F5] > To: <0406673789>;tag=3289504173 172.16.165.249 25/10 15:00:40.064

<191>syslog: SipSignaling [00F6] > Call-ID:

25da2052-377ad195@192.168.1.2

172.16.165.249 25/10 15:00:40.064

<191>syslog: SipSignaling [00F7] > CSeq: 101 INVITE 172.16.165.249 25/10 15:00:40.064

<191>syslog: SipSignaling [00F8] > Server: Mediatrix 4402/v2.0.10.185 44XX-MX-D2000-66 172.16.165.249 25/10 15:00:40.064

<191>syslog: SipSignaling [00F9] > Content-Length: 0 172.16.165.249 25/10 15:00:40.064

<191>syslog: SipSignaling [00FA] > 172.16.165.249 25/10 15:00:40.064

<191>syslog: SipSignaling [00FB] < [192.168.1.1:5060] Received SIP packet from: 192.168.1.2:5060 172.16.165.249 25/10 15:00:40.064

<191>syslog: SipSignaling [00FC] < ACK sip:0406673789@192.168.1.1 SIP/2.0 172.16.165.249 25/10 15:00:40.064

<191>syslog: SipSignaling [00FD] < Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bK-724e226a 172.16.165.249 25/10 15:00:40.064

<191>syslog: SipSignaling [00FE] < From: Excelsior Gold <0893357770>;tag=6c52992e7a134e69o5;ref=105 172.16.165.249 25/10 15:00:40.064

<191>syslog: SipSignaling [00FF] < To: <0406673789>;tag=3289504173 172.16.165.249 25/10 15:00:40.064

<191>syslog: SipSignaling [0100] < Call-ID:

25da2052-377ad195@192.168.1.2

172.16.165.249 25/10 15:00:40.064

<191>syslog: SipSignaling [0101] < CSeq: 101 ACK 172.16.165.249 25/10 15:00:40.064

<191>syslog: SipSignaling [0102] < Max-Forwards: 70 172.16.165.249 25/10 15:00:40.080

<191>syslog: SipSignaling [0103] < Contact: Excelsior Gold <0893357770> 172.16.165.249 25/10 15:00:40.080

<191>syslog: SipSignaling [0104] < User-Agent: Cisco/UC320W-2.1.1(7) 172.16.165.249 25/10 15:00:40.080

<191>syslog: SipSignaling [0105] < Allow-Events: talk, hold, conference, x-spa-cti 172.16.165.249 25/10 15:00:40.080

<191>syslog: SipSignaling [0106] < Content-Length: 0 172.16.165.249 25/10 15:00:40.080

<191>syslog: SipSignaling [0107] < 172.16.165.249 25/10 15:00:40.080

<191>syslog: IsdnStackL2State [0108] PH - Primitive request (PH Data Indication) to If (0) 172.16.165.249 25/10 15:00:40.080

<191>syslog: IsdnStackL2Raw [0109] 0) < [ 00 83 01 16 ] 172.16.165.249 25/10 15:00:40.080

<191>syslog: IsdnStackL2Msg [010A] 0) < [Supervisory frame] 172.16.165.249 25/10 15:00:40.080

<191>syslog: IsdnStackL2Msg [010B] 0) < SAPI: 00 C/R: 0 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:40.080

<191>syslog: IsdnStackL2Msg [010C] 0) < N(R): 011 SS: 0 P/F: 0 [RR Receiver Ready] 172.16.165.249 25/10 15:00:40.080

<191>syslog: IsdnStackL2State [010D] 0) ACKing all packets from 10 to (but not including) 11 172.16.165.249 25/10 15:00:40.080

<191>syslog: IsdnStackL2State [010E] 0) Stopping T200 Timer 172.16.165.249 25/10 15:00:40.080

<191>syslog: IsdnStackL2State [010F] 0) Stopping T203 Timer 172.16.165.249 25/10 15:00:40.080

<191>syslog: IsdnStackL2State [0110] 0) Starting T203 Timer 172.16.165.249 25/10 15:00:40.095

<014>Isdn: 1850-Integrated Services Digital Network: 40-Bri1, B-channel 1: State changed to used. 172.16.165.249 25/10 15:00:40.095

<191>syslog: IsdnStackL2State [0111] PH - Primitive request (PH Data Indication) to If (0) 172.16.165.249 25/10 15:00:40.376

<191>syslog: IsdnStackL2Raw [0112] 0) < [ 02 83 10 16 08 01 8f 4d ] 172.16.165.249 25/10 15:00:40.376

<191>syslog: IsdnStackL2Msg [0113] 0) < [Informational frame] 172.16.165.249 25/10 15:00:40.392

<191>syslog: IsdnStackL2Msg [0114] 0) < SAPI: 00 C/R: 1 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:40.392

<191>syslog: IsdnStackL2Msg [0115] 0) < N(R): 011 N(S): 008 P/F: 0 172.16.165.249 25/10 15:00:40.407

<191>syslog: IsdnStackL2Msg [0116] 0) < VR: 008 VS: 011 VA: 011 172.16.165.249 25/10 15:00:40.407

<191>syslog: IsdnStackL2Msg [0117] 0) > [Supervisory frame] 172.16.165.249 25/10 15:00:40.407

<191>syslog: IsdnStackL2Msg [0118] 0) > SAPI: 00 C/R: 1 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:40.423

<191>syslog: IsdnStackL2Msg [0119] 0) > N(R): 009 SS: 0 P/F: 0 [ RR Receiver Ready ] 172.16.165.249 25/10 15:00:40.423

<191>syslog: IsdnStackL2Raw [011A] 0) > [ 02 83 01 12 ] 172.16.165.249 25/10 15:00:40.439

<191>syslog: IsdnStackL2State [011B] 0) ACKing all packets from 11 to (but not including) 11 172.16.165.249 25/10 15:00:40.439

<191>syslog: IsdnStackL2State [011C] 0) Stopping T200 Timer 172.16.165.249 25/10 15:00:40.439

<191>syslog: IsdnStackL2State [011D] 0) Stopping T203 Timer 172.16.165.249 25/10 15:00:40.454

<191>syslog: IsdnStackL2State [011E] 0) Starting T203 Timer 172.16.165.249 25/10 15:00:40.454

<191>syslog: IsdnStackL3Msg [011F] DL - Primitive request (DL Data Indication) to If (0) 172.16.165.249 25/10 15:00:40.454

<191>syslog: IsdnStackL3Msg [0120] 0 < Call 15-Outbound TEI 65 Unicast RECV Release (77) 172.16.165.249 25/10 15:00:40.470

<191>syslog: IsdnStackL3State [0121] CIsdnState::DispatchIsdnMsg - Release message dispatched to call 15 (OutBound) 172.16.165.249 25/10 15:00:40.470

<191>syslog: IsdnStackL3State [0122] ISDN if 0, Call 15-Outbound: Stopping T305 Timer in state U11_DISCONNECT_REQUEST. 172.16.165.249 25/10 15:00:40.470

<191>syslog: IsdnStackL3Msg [0123] 0 > Call 15-Outbound TEI 65 SEND Release Complete (90) 172.16.165.249 25/10 15:00:40.470

<191>syslog: IsdnStackL3State [0124] Call 0xf changed state from U11_DISCONNECT_REQUEST to U0_NULL_STATE 172.16.165.249 25/10 15:00:40.470

<191>syslog: IsdnStackL3Msg [0125] Releasing Call 15-Outbound 172.16.165.249 25/10 15:00:40.485

<191>syslog: IsdnStackL1State [0126] PH - Primitive request (PH Data Request) to If (0) 172.16.165.249 25/10 15:00:40.485

<191>syslog: IsdnStackL2State [0127] DL-Primitive request (DL Data Request) to If (0) 172.16.165.249 25/10 15:00:40.485

<191>syslog: IsdnStackL2State [0128] 0) Stopping T203 Timer 172.16.165.249 25/10 15:00:40.485

<191>syslog: IsdnStackL2State [0129] 0) Starting T200 Timer 172.16.165.249 25/10 15:00:40.485

<191>syslog: IsdnStackL2Msg [012A] 0) > [Informational frame] 172.16.165.249 25/10 15:00:40.485

<191>syslog: IsdnStackL2Msg [012B] 0) > SAPI: 00 C/R: 0 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:40.501

<191>syslog: IsdnStackL2Msg [012C] 0) > N(R): 009 N(S): 011 P/F: 0 [ Informational ] 172.16.165.249 25/10 15:00:40.501

<191>syslog: IsdnStackL2Raw [012D] 0) > [ 00 83 16 12 08 01 0f 5a ] 172.16.165.249 25/10 15:00:40.501

<191>syslog: IsdnStackL1State [012E] PH - Primitive request (PH Data Request) to If (0) 172.16.165.249 25/10 15:00:40.501

<191>syslog: IsdnInterface [012F] L1 B1 Call 15-Outbound: Received ISDN message "Release Indication" (14) for state AwaitReleasing. 172.16.165.249 25/10 15:00:40.501

<191>syslog: IsdnInterface [0130] L1 B1 - Failed stopping hairpinning channels 172.16.165.249 25/10 15:00:40.501

<191>syslog: CallTable [0131] ReleaseCall - Interface isdn-Bri1 try to release call 54. 172.16.165.249 25/10 15:00:40.517

<191>syslog: CallTable [0132] ReleaseCall - Interface isdn-Bri1 release call 54. 172.16.165.249 25/10 15:00:40.517

<191>syslog: CallTable [0133] ReleaseCall - Call 52-54 released. 172.16.165.249 25/10 15:00:40.517

<191>syslog: LineEngine [0134] EP1 StopTone 172.16.165.249 25/10 15:00:40.517

<191>syslog: IsdnInterface [0135] L1 B1 - Change state from "AwaitReleasing" to "Idle" 172.16.165.249 25/10 15:00:40.517

<191>syslog: CommandDigitInt [0136] L1 N1 - Event Terminate() on state "FINAL" 172.16.165.249 25/10 15:00:40.517

<191>syslog: CommandDigitInt [0137] L1 N1 - Event Terminate was not handled by state "FINAL", send the event to his parent "ROOT" 172.16.165.249 25/10 15:00:40.517

<191>syslog: CommandDigitInt [0138] L1 N1 - Change state from "FINAL" to "FINAL" 172.16.165.249 25/10 15:00:40.532

<191>syslog: LineEngine [0139] EP1 Released. 172.16.165.249 25/10 15:00:40.532

<191>syslog: LineEngine [013A] EP1 LowLevel report channel closed : id=0 172.16.165.249 25/10 15:00:40.532

<191>syslog: CallManager [013B] C54 - CallReleaseA(16, -1) 172.16.165.249 25/10 15:00:40.532

<191>syslog: IsdnStackL2State [013C] PH - Primitive request (PH Data Indication) to If (0) 172.16.165.249 25/10 15:00:40.532

<191>syslog: IsdnStackL2Raw [013D] 0) < [ 00 83 01 18 ] 172.16.165.249 25/10 15:00:40.532

<191>syslog: IsdnStackL2Msg [013E] 0) < [Supervisory frame] 172.16.165.249 25/10 15:00:40.532

<191>syslog: IsdnStackL2Msg [013F] 0) < SAPI: 00 C/R: 0 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:40.532

<191>syslog: IsdnStackL2Msg [0140] 0) < N(R): 012 SS: 0 P/F: 0 [RR Receiver Ready] 172.16.165.249 25/10 15:00:40.532

<191>syslog: IsdnStackL2State [0141] 0) ACKing all packets from 11 to (but not including) 12 172.16.165.249 25/10 15:00:40.548

<191>syslog: IsdnStackL2State [0142] 0) Stopping T200 Timer 172.16.165.249 25/10 15:00:40.548

<191>syslog: IsdnStackL2State [0143] 0) Stopping T203 Timer 172.16.165.249 25/10 15:00:40.548

<191>syslog: IsdnStackL2State [0144] 0) Starting T203 Timer 172.16.165.249 25/10 15:00:40.548

<191>syslog: Admin [0145] Bri1 usage state is now Idle. 172.16.165.249 25/10 15:00:40.548

<191>syslog: Admin [0146] Slot0 usage state is now Idle. 172.16.165.249 25/10 15:00:40.548

<191>syslog: Admin [0147] Unit usage state is now Idle. 172.16.165.249 25/10 15:00:40.548

<014>Isdn: 1850-Integrated Services Digital Network: 30-Bri1, B-channel 1: State changed to free. 172.16.165.249 25/10 15:00:40.548

<191>syslog: IsdnStackL2State [0148] LAPD if 0: Timer T203 expired in state 7_LINK_CONNECTION_ESTABLISHED 172.16.165.249 25/10 15:00:50.438

<191>syslog: IsdnStackL2Msg [0149] 0) > [Supervisory frame] 172.16.165.249 25/10 15:00:50.438

<191>syslog: IsdnStackL2Msg [014A] 0) > SAPI: 00 C/R: 0 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:50.438

<191>syslog: IsdnStackL2Msg [014B] 0) > N(R): 009 SS: 0 P/F: 1 [ RR Receiver Ready ] 172.16.165.249 25/10 15:00:50.454

<191>syslog: IsdnStackL2Raw [014C] 0) > [ 00 83 01 13 ] 172.16.165.249 25/10 15:00:50.454

<191>syslog: IsdnStackL2State [014D] 0) Starting T200 Timer 172.16.165.249 25/10 15:00:50.469

<191>syslog: IsdnStackL2State [014E] CLapdState::SetState - If 00 changed from 7_LINK_CONNECTION_ESTABLISHED to 8_TIMER_RECOVERY 172.16.165.249 25/10 15:00:50.469

<191>syslog: IsdnStackL1State [014F] PH - Primitive request (PH Data Request) to If (0) 172.16.165.249 25/10 15:00:50.485

<191>syslog: IsdnStackL2State [0150] PH - Primitive request (PH Data Indication) to If (0) 172.16.165.249 25/10 15:00:50.485

<191>syslog: IsdnStackL2Raw [0151] 0) < [ 02 83 01 19 ] 172.16.165.249 25/10 15:00:50.501

<191>syslog: IsdnStackL2Msg [0152] 0) < [Supervisory frame] 172.16.165.249 25/10 15:00:50.501

<191>syslog: IsdnStackL2Msg [0153] 0) < SAPI: 00 C/R: 1 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:50.501

<191>syslog: IsdnStackL2Msg [0154] 0) < N(R): 012 SS: 0 P/F: 1 [RR Receiver Ready] 172.16.165.249 25/10 15:00:50.516

<191>syslog: IsdnStackL2Msg [0155] 0) > [Supervisory frame] 172.16.165.249 25/10 15:00:50.516

<191>syslog: IsdnStackL2Msg [0156] 0) > SAPI: 00 C/R: 1 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:50.516

<191>syslog: IsdnStackL2Msg [0157] 0) > N(R): 009 SS: 0 P/F: 1 [ RR Receiver Ready ] 172.16.165.249 25/10 15:00:50.516

<191>syslog: IsdnStackL2Raw [0158] 0) > [ 02 83 01 13 ] 172.16.165.249 25/10 15:00:50.516

<191>syslog: IsdnStackL2State [0159] 0) ACKing all packets from 12 to (but not including) 12 172.16.165.249 25/10 15:00:50.532

<191>syslog: IsdnStackL1State [015A] PH - Primitive request (PH Data Request) to If (0) 172.16.165.249 25/10 15:00:50.532

<191>syslog: IsdnStackL2State [015B] PH - Primitive request (PH Data Indication) to If (0) 172.16.165.249 25/10 15:00:50.532

<191>syslog: IsdnStackL2Raw [015C] 0) < [ 00 83 01 19 ] 172.16.165.249 25/10 15:00:50.532

<191>syslog: IsdnStackL2Msg [015D] 0) < [Supervisory frame] 172.16.165.249 25/10 15:00:50.532

<191>syslog: IsdnStackL2Msg [015E] 0) < SAPI: 00 C/R: 0 EA: 0 TEI: 065 EA: 1 172.16.165.249 25/10 15:00:50.547

<191>syslog: IsdnStackL2Msg [015F] 0) < N(R): 012 SS: 0 P/F: 1 [RR Receiver Ready] 172.16.165.249 25/10 15:00:50.547

<191>syslog: IsdnStackL2State [0160] 0) ACKing all packets from 12 to (but not including) 12 172.16.165.249 25/10 15:00:50.547

<191>syslog: IsdnStackL2State [0161] 0) Stopping T200 Timer 172.16.165.249 25/10 15:00:50.547

<191>syslog: IsdnStackL2State [0162] 0) Stopping T203 Timer 172.16.165.249 25/10 15:00:50.547

<191>syslog: IsdnStackL2State [0163] 0) Starting T203 Timer 172.16.165.249 25/10 15:00:50.547

<191>syslog: IsdnStackL2State [0164] CLapdState::SetState - If 00 changed from 8_TIMER_RECOVERY to 7_LINK_CONNECTION_ESTABLISHED 172.16.165.249 25/10 15:00:50.563

mmartin84 · ‎10-25-2011

Sorry for the paste in the message, but I cant see an option to add a .txt file attachment...

David Harper · ‎10-25-2011

Ok, looks like we have an ISDN interworking problem happening. Most likely there is a config error on the gateway, but it could still be a network thing. Can you post a screenshot of the ISDN > Basic Rate Interface screen please?

Cheers,

Dave.

mmartin84 · ‎10-25-2011

I had just finished taking this screen shot when I saw your reply, thought the logs where pointing to something here!

David Harper · ‎10-25-2011

Ok, that all looks good. Re-reading the logs, it looks like the network is popping a non fatal error upon receipt of the calling party name and as a result the gateway is tearing down the call. Have a look at ISDN > Services, and see if anything is enabled there. If so, start by disabling everything, and see if you can then make a call. If that works, then we can look at enabling at least the presentation of CLID, which is about all you would be able to have enabled anyway.

Cheers,

Dave.

mmartin84 · ‎10-25-2011

The only thing that was enabled was "call line Information Presentation" I have disabled that and still have the same issue.

Thank you for your ongoing assistance!