SMG-4 Asterisk и Е1

[Svlel]

Доброго всем дня.

Возникла такая ситуация:
От провайдера приходят несколько номеров по E1, далее они передаются на Asterisk.
Соединение снаружи по данным номерам проходит, но буквально через пять секунд следует разрыв соединения.

Лог pbx_pstn

SMG-4. SN: VI3F000195 Software Version: V.3.1.2.1101. 4/S Build: Nov 18 2015 09:51:54
Log started at: 13:36:46.507777
13:37:06.139991 [INFO] Port PRI:00:00. VChan set (chan 14) - 'line 0, chan 56'
13:37:06.140117 [INFO] Port PRI:00:00. Set direct prefix [1]
13:37:06.140173 [INFO] Port PRI:00:00. Seize (v-chan:14, TG:00). Cld:'<none>'(0). (Trunk) . Clg-len: 0. clg-set: n. COS: -1. RADIUS=-1
13:37:06.140230 [INFO] Port PRI:00:00. ModTable in [-1:-1], out [-1:-1], out redir:orig [-1:-1]
13:37:06.140274 [INFO] Port PRI:00:00. Set calling number: calling not set. Cat [
13:37:06.140313 [INFO] Port PRI:00:00. Calling number: none, use for sorm: all digits
13:37:06.140376 [INFO] Port PRI:00:00. Calling Info (pres not allowed): <none>
13:37:06.140442 [INFO] Port PRI:00:00. CgPN: <none>(0) <not set> <unknown> <no-change> <restricted> <net.provided>. cat [
13:37:06.140498 [INFO] Port PRI:00:00. Set state 'In-Dial'
13:37:06.140548 [INFO] Port PRI:00:00. Direct route to pfx[1]
13:37:06.140788 [INFO] Port PRI:00:00. Dial In (in=08, need rm=0): <5><3><9><9><4><4><4>[.]
13:37:06.140854 [INFO] Port PRI:00:00. In Digit 8 sym: called buf <5399444.>
13:37:06.140893 [INFO] Port PRI:00:00. Dial buf <5399444>(7)
13:37:06.140937 [INFO] Port PRI:00:00. Dial Proc (state In-Dial, called len 08): <5399444.> Compl.
13:37:06.140990 [INFO] Port PRI:00:00. Dial Proc. RADIUS return-code: [0].
13:37:06.141046 [INFO] Port PRI:00:00. Search route. Mode: 'called'. Num: <5399444.>(8).# Complete
13:37:06.141087 [INFO] Port PRI:00:00. Direct route to pfx [1] set. L[10], S[5], D[30]
13:37:06.141132 [INFO] Port PRI:00:00. Process route to prefix[1].
13:37:06.141175 [INFO] Port PRI:00:00. Send 'End of Dial' to incoming call
13:37:06.141289 [INFO] Port PRI:00:00. Prefix 01: type 'TRUNK', idx=1
13:37:06.141337 [INFO] Port PRI:00:00. Accs on
13:37:06.141382 [INFO] Port PRI:00:00. Link to TG 01. Out modifiers-table: clg[-1], cld[-1], redir[-1], orig[-1], generic[-1]
13:37:06.141427 [INFO] Port PRI:00:00. Link to TG 01. Setup mode: enblock <ST>
13:37:06.141469 [INFO] Port PRI:00:00. Link to TG 01: mode Local. Dir=0, Cld=0 Select Order=. In buf: ~5399444.
13:37:06.141513 [INFO] Port PRI:00:00. TG: Link entry to SIPT[00]
13:37:06.141557 [INFO] Port PRI:00:00. Outgoing setup to SIPT:0000.
13:37:06.141637 [INFO] Port SIPT:0426. Check out-calling-modify: ''(0) not set. ModTable[-1], ClgMod[-1]
13:37:06.141691 [INFO] Port SIPT:0426. Check out-calling-from-RADIUS-modify: ''(0) not set. ClgMod[-1]
13:37:06.141753 [INFO] Port SIPT:0426. Set parent PRI:00:00
13:37:06.141795 [INFO] Port SIPT:0426. VChanIP set - 'line 0, chan 56'
13:37:06.141860 [INFO] Port SIPT:0426. Create msp-conn Conn[000e].
13:37:06.142060 [INFO] Port SIPT:0426. Set new IP Conn[000e] with chan[56]
13:37:06.142136 [INFO] Port SIPT:0426. loc 0, trunk-loc 0. peer-loc 0, peer-tunk-loc: 0
13:37:06.142182 [INFO] Port PRI:00:00. loc 0, trunk-loc 0. peer-loc 0, peer-tunk-loc: 0
13:37:06.142242 [INFO] Port SIPT:0426. Set state 'Wait-Num'
13:37:06.142295 [INFO] Port SIPT:0426. Query Next Digit - peer PRI:00:00 (next.digit=n). Called len 08, proceed 00
13:37:06.142338 [INFO] Port SIPT:0426. Dial Out=5 (ext)
13:37:06.142421 [INFO] Port SIPT:0426. Check out-called-modify: '5'(1). ModTable[-1], CldMod[-1]
13:37:06.142474 [INFO] Port SIPT:0426. Dial Out: called len 00, append 01 (max digit 30)
13:37:06.142529 [INFO] Port SIPT:0426. Query Next Digit - peer PRI:00:00 (next.digit=n). Called len 08, proceed 01
13:37:06.142570 [INFO] Port SIPT:0426. Dial Out=3 (ext)
13:37:06.142614 [INFO] Port SIPT:0426. Dial Out: called len 01, append 01 (max digit 30)
13:37:06.142666 [INFO] Port SIPT:0426. Query Next Digit - peer PRI:00:00 (next.digit=n). Called len 08, proceed 02
13:37:06.142706 [INFO] Port SIPT:0426. Dial Out=9 (ext)
13:37:06.142748 [INFO] Port SIPT:0426. Dial Out: called len 02, append 01 (max digit 30)
13:37:06.142864 [INFO] Port SIPT:0426. Query Next Digit - peer PRI:00:00 (next.digit=n). Called len 08, proceed 03
13:37:06.143089 [INFO] Port SIPT:0426. Dial Out=9 (ext)
13:37:06.143151 [INFO] Port SIPT:0426. Dial Out: called len 03, append 01 (max digit 30)
13:37:06.143206 [INFO] Port SIPT:0426. Query Next Digit - peer PRI:00:00 (next.digit=n). Called len 08, proceed 04
13:37:06.143247 [INFO] Port SIPT:0426. Dial Out=4 (ext)
13:37:06.143290 [INFO] Port SIPT:0426. Dial Out: called len 04, append 01 (max digit 30)
13:37:06.143341 [INFO] Port SIPT:0426. Query Next Digit - peer PRI:00:00 (next.digit=n). Called len 08, proceed 05
13:37:06.143381 [INFO] Port SIPT:0426. Dial Out=4 (ext)
13:37:06.143447 [INFO] Port SIPT:0426. Dial Out: called len 05, append 01 (max digit 30)
13:37:06.143503 [INFO] Port SIPT:0426. Query Next Digit - peer PRI:00:00 (next.digit=n). Called len 08, proceed 06
13:37:06.143545 [INFO] Port SIPT:0426. Dial Out=4. (ext)
13:37:06.143590 [INFO] Port SIPT:0426. Dial Out: called len 06, append 02 (max digit 30)
13:37:06.143632 [INFO] Port SIPT:0426. Dial Out: 'End_of_Dial' digit/stop dial
13:37:06.143678 [INFO] Port SIPT:0426. Setup Ack (peer=PRI:00:00)
13:37:06.143720 [INFO] Port SIPT:0426. Set state 'Out-Dial'
13:37:06.143763 [INFO] Port PRI:00:00. Setup Acked in state In-Dial. (peer=SIPT:0426)
13:37:06.143806 [INFO] Port PRI:00:00. LinkUp to SIPT:0426
13:37:06.143848 [INFO] Port SIPT:0426. Activate IP-conn [000e]
13:37:06.143888 [INFO] Conn[000e]: try activate. state 'AllocReq'.no media
13:37:06.143988 [INFO] Port PRI:00:00. Get CallerId: '-none-' (0) no set-flg
13:37:06.145252 [INFO] Port PRI:00:00. Prefix linked: called len 08, proceed 08
13:37:06.146615 [INFO] Port SIPT:0426. Created IP-conn [000e].
13:37:06.146679 [INFO] Conn[000e]: try activate. state 'Disabled'.no media
13:37:06.487373 [INFO] Port SIPT:0426. Alert (peer=PRI:00:00)
13:37:06.487445 [INFO] Port SIPT:0426. Stop Dial, reason 'alert'
13:37:06.487501 [INFO] Port PRI:00:00. LinkUp to SIPT:0426
13:37:06.487546 [INFO] Port SIPT:0426. Activate IP-conn [000e]
13:37:06.487588 [INFO] Conn[000e]: try activate. state 'Disabled'.no media
13:37:06.487631 [INFO] Port SIPT:0426. Set state 'Out-Call'
13:37:06.487672 [INFO] Port PRI:00:00. Set state 'In-Call'
13:37:06.487718 [INFO] Port PRI:00:00. LinkUp to SIPT:0426
13:37:06.487760 [INFO] Port SIPT:0426. Activate IP-conn [000e]
13:37:06.487797 [INFO] Conn[000e]: try activate. state 'Disabled'.no media
13:37:06.487840 [INFO] Port SIPT:0426. Dir[1], obci-req[1]. Call-ind: change[1], obci[0:0], isdn: allway[1], fwd_acs[0]
13:37:06.487913 [INFO] Port SIPT:0426. Dir[1], obci-req[0]. Call-ind: change[1], obci[0:0], isdn: allway[1], fwd_acs[0]
13:37:06.488057 [INFO] Port SIPT:0426. TDM-RingBack for IP-conn [000e], mode [0]
13:37:06.574675 [INFO] Conn[000e]: Tone started
13:37:09.526163 [INFO] Port PRI:00:00. Release, cause 'Normal call clearing', dcl '0', loc '0', peer 'SIPT:0426'
13:37:09.526277 [INFO] Port PRI:00:00. Save CDR. disabled. [0x0]
13:37:09.526326 [INFO] Port PRI:00:00. Set state 'Release'
13:37:09.526371 [INFO] Port PRI:00:00. Release peer 'SIPT:0426', cause 'Normal call clearing', dcl '7', loc '0'
13:37:09.526417 [INFO] Port SIPT:0426. Disconnect from PRI:00:00, cause 'Normal call clearing', dcl '7', loc '0'
13:37:09.526459 [INFO] Port SIPT:0426. Disconnect, cause 'Normal call clearing', dcl '7', loc '0'
13:37:09.526506 [INFO] Port SIPT:0426. Save CDR. disabled. [0x0]
13:37:09.526571 [INFO] Port SIPT:0426. Set signal: 'BUSY'
13:37:09.526629 [INFO] Port SIPT:0426. Deactivate IP-conn [000e]
13:37:09.526676 [INFO] Port SIPT:0426. Release, cause 'Normal call clearing', dcl '0', loc '0'
13:37:09.526718 [INFO] Port SIPT:0426. Save CDR. disabled. [0x0]
13:37:09.526759 [INFO] Port SIPT:0426. Set state 'Release'
13:37:09.526797 [INFO] Port SIPT:0426. Free IP-conn [000e]
13:37:09.526903 [INFO] Port SIPT:0426. Destroy Conn[000e].
13:37:09.546738 [INFO] Port SIPT:0426. Release Complete, cause 'Normal call clearing', dcl '0', loc '0'
13:37:09.546844 [INFO] Port SIPT:0426. Save CDR. disabled. [0x0]
13:37:09.546907 [INFO] Port SIPT:0426. Set state 'Ready'
13:37:09.553530 [INFO] Port PRI:00:00. Release Complete, cause 'Normal, unspecified', dcl '0', loc '1'
13:37:09.553617 [INFO] Port PRI:00:00. Save CDR. disabled. [0x0]
13:37:09.553679 [INFO] Port PRI:00:00. Set state 'Ready'
SMG-4. SN: VI3F000195 Software Version: V.3.1.2.1101. 4/S Build: Nov 18 2015 09:51:54

Что может вызывать данную проблему?

[Женя]

Похоже что по q931 получаем отбой, снимите более полные логи, все уровни поставьте =1

[Svlel]

Более полные логи:

pbx_pstn

SMG-4. SN: VI3F000195 Software Version: V.3.1.2.1101. 4/S Build: Nov 18 2015 09:51:54
Log started at: 15:04:27.111416
15:04:31.527034 [INFO] PBXIPC-SIP. TX. trace
15:04:31.527126 [INFO] # trace-level [5]
15:04:31.581292 [INFO] PBXIPC-SIP. RX. trace
15:04:31.581357 [INFO] # trace-level [5]
15:05:09.881737 [INFO] PBXIPC-SIP. RX. keep-alive-req
15:05:09.881801 [INFO] # requestID 00de
15:05:09.881841 [INFO] # trunkID 01
15:05:09.881878 [INFO] # Hostname '10.0.0.103'
15:05:09.881915 [INFO] # port 5060
15:05:09.882113 [INFO] SIP. Request 00de. Got keep-alive request for trunkID [1] (outside of dialog)
15:05:09.882188 [INFO] SIP. Callref 00de. Media-Info encode. Media-list size: 1
15:05:09.882273 [INFO] SIP. Request 00de. Send keep-alive reply for trunkID [1]
15:05:09.882321 [INFO] PBXIPC-SIP. TX. keep-alive-rsp
15:05:09.882358 [INFO] # requestID 00de
15:05:09.882395 [INFO] # trunkID 01
15:05:09.882430 [INFO] # SDP len (185)
15:05:09.882465 [INFO] # cause 200
15:05:34.313644 [INFO] Q931. Line 00/00. Call AEAA. RX 30
DUMP: 08.02.2E.AA.05.A1.04.03.90.90.A3.18.03.A9.83.8F.
1E.02.81.83.70.08.81.35.33.39.39.34.34.34.
0x2EAA (from orig), MSG=SETUP:
[sending complete]
[bearer capability:
cap=3.1 kHz audio
std=CCITT
rate=64 kbit/s
mode=circuit
layer1=G.711 A-law]
[channel id: channel=15 (exclusive)] Coding=CCITT
[progress ind: Origin not isdn]
[called party number: 5399444 (type=unknown, plan=ISDN)]
---------------------------------
15:05:34.313760 [INFO] Q931. Line 00/00. Create Call, entry 00. Call AEAA (Incoming)
15:05:34.313810 [INFO] Q931. Line 00/00. Call AEAA. Incoming SETUP. Check chan id
15:05:34.313852 [INFO] Check IE 'Channel ID': channel id='as indicated' chan=15, mode excl
15:05:34.313900 [INFO] Q931. Line 00/00. Search B-chan: chan 15, mask 00010001 - chan ok: mask 00010001
15:05:34.313939 [INFO] Check IE 'Bearer capablity: {3.1 kHz audio}{64 kbit/s}{G.711 A-law}
15:05:34.313984 [INFO] Check IE 'Called party number': {type=0x00, plan=0x01} <5399444> (7)
15:05:34.314025 [INFO] Q931. Line 00/00. Call AEAA. Incoming SETUP. {PI 3} CgPN <>(0), CdPN <5399444>(7) isdn flag=02
15:05:34.314096 [INFO] Port PRI:00:00. VChan set (chan 15) - 'line 0, chan 60'
15:05:34.314160 [INFO] Port PRI:00:00. Set direct prefix [1]
15:05:34.314202 [INFO] Port PRI:00:00. Seize (v-chan:15, TG:00). Cld:'<none>'(0). (Trunk) . Clg-len: 0. clg-set: n. COS: -1. RADIUS=-1
15:05:34.314250 [INFO] Port PRI:00:00. ModTable in [-1:-1], out [-1:-1], out redir:orig [-1:-1]
15:05:34.314294 [INFO] Port PRI:00:00. Set calling number: calling not set. Cat [
15:05:34.314334 [INFO] Port PRI:00:00. Calling number: none, use for sorm: all digits
15:05:34.314376 [INFO] Port PRI:00:00. Calling Info (pres not allowed): <none>
15:05:34.314420 [INFO] Port PRI:00:00. CgPN: <none>(0) <not set> <unknown> <no-change> <restricted> <net.provided>. cat [
15:05:34.314467 [INFO] Port PRI:00:00. Set state 'In-Dial'
15:05:34.314507 [INFO] Port PRI:00:00. Direct route to pfx[1]
15:05:34.314548 [INFO] Q931. Line 00/00. Call AEAA. Incoming seize - PLAN 0. COS 0
15:05:34.314588 [INFO] Q931. Line 00/00. Call AEAA. Incoming SETUP. {PI 3} proc dial
15:05:34.314628 [INFO] Q931. Line 00/00. Call AEAA. State 'Overlap Receiving'
15:05:34.314672 [INFO] Q931. Line 00/00. Call AEAA. In Dial: 5399444{EndOfDial}
15:05:34.314715 [INFO] Q931. Line 00/00. Call AEAA. Timer 'T302' (15 sec) start in state 'Overlap Receiving'
15:05:34.314777 [INFO] Port PRI:00:00. Dial In (in=08, need rm=0): <5><3><9><9><4><4><4>[.]
15:05:34.314822 [INFO] Port PRI:00:00. In Digit 8 sym: called buf <5399444.>
15:05:34.314861 [INFO] Port PRI:00:00. Dial buf <5399444>(7)
15:05:34.314904 [INFO] Port PRI:00:00. Dial Proc (state In-Dial, called len 08): <5399444.> Compl.
15:05:34.314945 [INFO] Port PRI:00:00. Dial Proc. RADIUS return-code: [0].
15:05:34.314993 [INFO] Port PRI:00:00. Search route. Mode: 'called'. Num: <5399444.>(8).# Complete
15:05:34.315099 [INFO] Port PRI:00:00. Direct route to pfx [1] set. L[10], S[5], D[30]
15:05:34.315154 [INFO] Port PRI:00:00. Process route to prefix[1].
15:05:34.315201 [INFO] Port PRI:00:00. Send 'End of Dial' to incoming call
15:05:34.315242 [INFO] Q931. Line 00/00. Call AEAA. End Dial in state 'Overlap Receiving' (condition for call proceeding reached)
15:05:34.315286 [INFO] Q931. Line 00/00. Call AEAA. Timer 'T302' stop in state 'Overlap Receiving'
15:05:34.315358 [INFO] Q931. Line 00/00. Call AEAA. TX 11
DUMP: 08.02.AE.AA.02.18.03.A9.83.8F.
0x2EAA (to orig), MSG=CALL PROCEEDING:
[channel id: channel=15 (exclusive)] Coding=CCITT
---------------------------------
15:05:34.315483 [INFO] Q931. Line 00/00. Call AEAA. State 'Incoming Call Proceeding'
15:05:34.315537 [INFO] Port PRI:00:00. Prefix 01: type 'TRUNK', idx=1
15:05:34.315580 [INFO] Port PRI:00:00. Accs on
15:05:34.315622 [INFO] Port PRI:00:00. Link to TG 01. Out modifiers-table: clg[-1], cld[-1], redir[-1], orig[-1], generic[-1]
15:05:34.315667 [INFO] Port PRI:00:00. Link to TG 01. Setup mode: enblock <ST>
15:05:34.315711 [INFO] Port PRI:00:00. Link to TG 01: mode Local. Dir=0, Cld=0 Select Order=. In buf: ~5399444.
15:05:34.315754 [INFO] Port PRI:00:00. TG: Link entry to SIPT[00]
15:05:34.315800 [INFO] Port PRI:00:00. Outgoing setup to SIPT:0000.
15:05:34.315843 [INFO] SIPT[00]. Seize from port PRI:00:00.
15:05:34.315919 [INFO] Port SIPT:0427. Check out-calling-modify: ''(0) not set. ModTable[-1], ClgMod[-1]
15:05:34.315970 [INFO] Port SIPT:0427. Check out-calling-from-RADIUS-modify: ''(0) not set. ClgMod[-1]
15:05:34.316024 [INFO] SIPT[00]. Seize - interface 0 [ID: 01]: set host:port 10.0.0.103:5060
15:05:34.316073 [INFO] Port SIPT:0427. Set parent PRI:00:00
15:05:34.316113 [INFO] Port SIPT:0427. VChanIP set - 'line 0, chan 60'
15:05:34.316176 [INFO] Port SIPT:0427. Create msp-conn Conn[000f].
15:05:34.316216 [INFO] Conn[000f]: Set state 'Idle'->'AllocReq'
15:05:34.316398 [INFO] Port SIPT:0427. Set new IP Conn[000f] with chan[60]
15:05:34.316465 [INFO] Conn[000f]: set network interface in state 'AllocReq'. IP <10.0.0.28>. net-dev [1]
15:05:34.316508 [INFO] SIP. Callref 0427. IP-conn [000f] ready
15:05:34.316555 [INFO] Port SIPT:0427. loc 0, trunk-loc 0. peer-loc 0, peer-tunk-loc: 0
15:05:34.316597 [INFO] Port PRI:00:00. loc 0, trunk-loc 0. peer-loc 0, peer-tunk-loc: 0
15:05:34.316642 [INFO] Conn[000f]. Set owner Port SIPT:0427 (previous was SIPT:0427)
15:05:34.316708 [INFO] Conn[000f]: set network interface in state 'AllocReq'. IP <10.0.0.28>. net-dev [1]
15:05:34.316756 [INFO] SIPT[00]. Seize - dst '10.0.0.103:5060' src-port 0
15:05:34.316796 [INFO] SIPT[00]. Seize CgPN: <none>(0) <not set> <unknown> <no-change> <restricted> <net.provided>. cat [
15:05:34.316837 [INFO] SIPT[00]. Seize - calling number not present
15:05:34.316875 [INFO] SIPT[00]. Seize - calling number not present - enblock mode
15:05:34.316917 [INFO] Port SIPT:0427. Set state 'Wait-Num'
15:05:34.316968 [INFO] Port SIPT:0427. Query Next Digit - peer PRI:00:00 (next.digit=n). Called len 08, proceed 00
15:05:34.317009 [INFO] Port SIPT:0427. Dial Out=5 (ext)
15:05:34.317052 [INFO] Port SIPT:0427. Check out-called-modify: '5'(1). ModTable[-1], CldMod[-1]
15:05:34.317097 [INFO] SIP. Callref 0427. Dial 5
15:05:34.317136 [INFO] Port SIPT:0427. Dial Out: called len 00, append 01 (max digit 30)
15:05:34.317188 [INFO] Port SIPT:0427. Query Next Digit - peer PRI:00:00 (next.digit=n). Called len 08, proceed 01
15:05:34.317228 [INFO] Port SIPT:0427. Dial Out=3 (ext)
15:05:34.317270 [INFO] SIP. Callref 0427. Dial 3
15:05:34.317308 [INFO] Port SIPT:0427. Dial Out: called len 01, append 01 (max digit 30)
15:05:34.317358 [INFO] Port SIPT:0427. Query Next Digit - peer PRI:00:00 (next.digit=n). Called len 08, proceed 02
15:05:34.317486 [INFO] Port SIPT:0427. Dial Out=9 (ext)
15:05:34.317543 [INFO] SIP. Callref 0427. Dial 9
15:05:34.317584 [INFO] Port SIPT:0427. Dial Out: called len 02, append 01 (max digit 30)
15:05:34.317637 [INFO] Port SIPT:0427. Query Next Digit - peer PRI:00:00 (next.digit=n). Called len 08, proceed 03
15:05:34.317678 [INFO] Port SIPT:0427. Dial Out=9 (ext)
15:05:34.317721 [INFO] SIP. Callref 0427. Dial 9
15:05:34.317760 [INFO] Port SIPT:0427. Dial Out: called len 03, append 01 (max digit 30)
15:05:34.317810 [INFO] Port SIPT:0427. Query Next Digit - peer PRI:00:00 (next.digit=n). Called len 08, proceed 04
15:05:34.317850 [INFO] Port SIPT:0427. Dial Out=4 (ext)
15:05:34.317892 [INFO] SIP. Callref 0427. Dial 4
15:05:34.317930 [INFO] Port SIPT:0427. Dial Out: called len 04, append 01 (max digit 30)
15:05:34.318189 [INFO] Port SIPT:0427. Query Next Digit - peer PRI:00:00 (next.digit=n). Called len 08, proceed 05
15:05:34.318247 [INFO] Port SIPT:0427. Dial Out=4 (ext)
15:05:34.318293 [INFO] SIP. Callref 0427. Dial 4
15:05:34.318333 [INFO] Port SIPT:0427. Dial Out: called len 05, append 01 (max digit 30)
15:05:34.318384 [INFO] Port SIPT:0427. Query Next Digit - peer PRI:00:00 (next.digit=n). Called len 08, proceed 06
15:05:34.318426 [INFO] Port SIPT:0427. Dial Out=4. (ext)
15:05:34.318468 [INFO] SIP. Callref 0427. Dial 4.
15:05:34.318533 [INFO] Port SIPT:0427. Dial Out: called len 06, append 02 (max digit 30)
15:05:34.318576 [INFO] Port SIPT:0427. Dial Out: 'End_of_Dial' digit/stop dial
15:05:34.318613 [INFO] SIP. Callref 0427. New state 'SIPT_OVL_SENDING'
15:05:34.318658 [INFO] Port SIPT:0427. Setup Ack (peer=PRI:00:00)
15:05:34.318700 [INFO] Port SIPT:0427. Set state 'Out-Dial'
15:05:34.318743 [INFO] Port PRI:00:00. Setup Acked in state In-Dial. (peer=SIPT:0427)
15:05:34.318787 [INFO] Port PRI:00:00. LinkUp to SIPT:0427
15:05:34.318829 [INFO] Port SIPT:0427. Activate IP-conn [000f]
15:05:34.318868 [INFO] Conn[000f]: try activate. state 'AllocReq'.no media
15:05:34.318911 [INFO] SIP. Callref 0427. Prepare media requested
15:05:34.318963 [INFO] SIP. Callref 0427. Send Media-Info. [core/sipt_proc.c:1836]
15:05:34.319008 [INFO] SIP. Callref 0427. Media-Info (offer): [10.0.0.28]
15:05:34.319052 [INFO] SIP. Callref 0427.
o=mgapp 1440300225 625931937 IN IP4 10.0.0.28
c=IN IP4 10.0.0.28
15:05:34.319116 [INFO] Valid
m[0]: audio 10036 RTP/AVP 8 0 101
a[0]:8 G711.A [set]
a[1]:0 G711.U [set]
a[2]:101 NTE [set]
a[3]:ptime:20
a[4]:sendrecv
15:05:34.319154 [INFO] SIP. Callref 0427. Prepare media finished (should send)
15:05:34.319197 [INFO] SIP. Callref 0427. Mode: 'SIP' Destination: [10.0.0.103:5060] localport [0] (with media)
15:05:34.319246 [INFO] Port PRI:00:00. Get CallerId: '-none-' (0) no set-flg
15:05:34.319284 [INFO] SIP. Callref 0427. Get display name: <>(0)
15:05:34.319324 [INFO] SIP. Callref 0427. Seize (media ready)
15:05:34.319361 [INFO] SIP. Callref 0427. Media-Info encode. Media-list size: 1
15:05:34.319452 [INFO] PBXIPC-SIP. TX. seize
15:05:34.319602 [INFO] # callref 0427
15:05:34.319654 [INFO] # trunkID 01
15:05:34.319692 [INFO] # Hostname '10.0.0.103'
15:05:34.319729 [INFO] # port 5060
15:05:34.319766 [INFO] # cdpn <5399444> (7) cat 0x00
15:05:34.319802 [INFO] # SDP len (235)
15:05:34.323492 [INFO] Port PRI:00:00. Prefix linked: called len 08, proceed 08
15:05:34.323604 [INFO] Conn[000f]: Set state 'AllocReq'->'Allocated'
15:05:34.326038 [INFO] Conn[000f]: Set state 'Allocated'->'DisableReq'
15:05:34.326131 [INFO] Conn[000f]: Created (disabled). State 'DisableReq'
15:05:34.326173 [INFO] Conn[000f]: Set state 'DisableReq'->'Disabled'
15:05:34.326219 [INFO] Port SIPT:0427. Created IP-conn [000f].
15:05:34.326260 [INFO] Conn[000f]: try activate. state 'Disabled'.no media
15:05:34.721379 [INFO] PBXIPC-SIP. RX. answer
15:05:34.721480 [INFO] # callref 0427
15:05:34.721527 [INFO] # cause 180
15:05:34.721565 [INFO] # Call-ID len (32)
15:05:34.721601 [INFO] # Display name ''
15:05:34.721797 [INFO] SIP. Callref 0427. Response 180 in state 'SIPT_OVL_SENDING' call-ID: cST-5jNtw6Azk8t7wToZoWBI9WA8TnPv
15:05:34.721859 [INFO] SIP. Callref 0427. Set display name: <>(0)
15:05:34.721902 [INFO] SIP. Callref 0427. Alert in state 'SIPT_OVL_SENDING'
15:05:34.721941 [INFO] SIP. Callref 0427. New state 'SIPT_DELIVERED'
15:05:34.722015 [INFO] SIP. Callref 0427. ISDN flg: BCI=0x50: 'ISDN All Way' 'Change' 'Send'
15:05:34.722072 [INFO] Port SIPT:0427. Alert (peer=PRI:00:00)
15:05:34.722111 [INFO] Port SIPT:0427. Stop Dial, reason 'alert'
15:05:34.722163 [INFO] Port PRI:00:00. LinkUp to SIPT:0427
15:05:34.722205 [INFO] Port SIPT:0427. Activate IP-conn [000f]
15:05:34.722246 [INFO] Conn[000f]: try activate. state 'Disabled'.no media
15:05:34.722287 [INFO] Port SIPT:0427. Set state 'Out-Call'
15:05:34.722329 [INFO] Port PRI:00:00. Set state 'In-Call'
15:05:34.722375 [INFO] Port PRI:00:00. LinkUp to SIPT:0427
15:05:34.722415 [INFO] Port SIPT:0427. Activate IP-conn [000f]
15:05:34.722453 [INFO] Conn[000f]: try activate. state 'Disabled'.no media
15:05:34.722495 [INFO] Port SIPT:0427. Dir[1], obci-req[1]. Call-ind: change[1], obci[0:0], isdn: allway[1], fwd_acs[0]
15:05:34.722539 [INFO] Port SIPT:0427. Dir[1], obci-req[0]. Call-ind: change[1], obci[0:0], isdn: allway[1], fwd_acs[0]
15:05:34.722583 [INFO] Q931. Line 00/00. Call AEAA. Call Received. PI [2][0]
15:05:34.722625 [INFO] Q931. Line 00/00. Call AEAA. Send 'Alert'
15:05:34.722699 [INFO] Q931. Line 00/00. Call AEAA. TX 10
DUMP: 08.02.AE.AA.01.1E.02.80.82.
0x2EAA (to orig), MSG=ALERTING:
[progress ind: Destination not isdn]
---------------------------------
15:05:34.722822 [INFO] Q931. Line 00/00. Call AEAA. State 'Call Received'
15:05:34.722874 [INFO] Port SIPT:0427. TDM-RingBack for IP-conn [000f], mode [0]
15:05:34.722915 [INFO] Conn[000f]: RingBack. State 'Disabled', ip <not set>, flag <0>
15:05:34.753416 [INFO] Conn[000f]. Start tone 'RINGBACKTONE'(23), direction 'TDM' in state 'Disabled'
15:05:34.754714 [INFO] Conn[000f]: Tone started
15:05:37.399144 [INFO] Q931. Line 00/00. Call AEAA. RX 9
DUMP: 08.02.2E.AA.45.08.02.81.90.
0x2EAA (from orig), MSG=DISCONNECT:
[cause: Normal call clearing (location=private network serving local user, std=CCITT)]
---------------------------------
15:05:37.399260 [INFO] Q931. Line 00/00. Call AEAA. Recv 'Disconnect'. Cause: 'Normal call clearing'
15:05:37.399304 [INFO] Q931. Line 00/00. Call AEAA. State 'Release Request'
15:05:37.399349 [INFO] Q931. Line 00/00. Call AEAA. Timer 'T308' (4 sec) start in state 'Release Request'
15:05:37.399421 [INFO] Q931. Line 00/00. Call AEAA. TX 10
DUMP: 08.02.AE.AA.4D.08.02.81.90.
0x2EAA (to orig), MSG=RELEASE:
[cause: Normal call clearing (location=private network serving local user, std=CCITT)]
---------------------------------
15:05:37.399535 [INFO] Port PRI:00:00. Release, cause 'Normal call clearing', dcl '0', loc '0', peer 'SIPT:0427'
15:05:37.399594 [INFO] Port PRI:00:00. Save CDR. disabled. [0x0]
15:05:37.399640 [INFO] Port PRI:00:00. Set state 'Release'
15:05:37.399684 [INFO] Port PRI:00:00. Release peer 'SIPT:0427', cause 'Normal call clearing', dcl '7', loc '0'
15:05:37.399731 [INFO] Port SIPT:0427. Disconnect from PRI:00:00, cause 'Normal call clearing', dcl '7', loc '0'
15:05:37.399773 [INFO] Port SIPT:0427. Disconnect, cause 'Normal call clearing', dcl '7', loc '0'
15:05:37.399820 [INFO] Port SIPT:0427. Save CDR. disabled. [0x0]
15:05:37.399862 [INFO] Port SIPT:0427. Set signal: 'BUSY'
15:05:37.399909 [INFO] SIP. Callref 0427. Release, cause 'Normal call clearing', loc '0'
15:05:37.399944 [INFO] SIP. Callref 0427. Disconnect. cause 'Normal call clearing', loc '0', reply '0'
15:05:37.400051 [INFO] Port SIPT:0427. Deactivate IP-conn [000f]
15:05:37.400099 [INFO] Conn[000f]: Deactivate in state 'Disabled'
15:05:37.400144 [INFO] Port SIPT:0427. Release, cause 'Normal call clearing', dcl '0', loc '0'
15:05:37.400186 [INFO] Port SIPT:0427. Save CDR. disabled. [0x0]
15:05:37.400228 [INFO] Port SIPT:0427. Set state 'Release'
15:05:37.400268 [INFO] Port SIPT:0427. Free IP-conn [000f]
15:05:37.400310 [INFO] Conn[000f]: Destroy in state 'Disabled'. [check]
15:05:37.400347 [INFO] Port SIPT:0427. Destroy Conn[000f].
15:05:37.400384 [INFO] Conn[000f]: Set state 'Disabled'->'DeallocReq'
15:05:37.400548 [INFO] SIP. Callref 0427. New state 'SIPT_RELEASE_REQUEST'
15:05:37.400996 [INFO] SIP. Callref 0427. Disconnect
15:05:37.401078 [INFO] PBXIPC-SIP. TX. rel-req
15:05:37.401161 [INFO] # callref 0427
15:05:37.401203 [INFO] # q850-cause 16
15:05:37.401240 [INFO] # cause 200
15:05:37.402474 [INFO] Conn[000f]: Destroyed
15:05:37.402570 [INFO] Conn[000f]: clr rtp-cfg. <10.0.0.28:10036>:[02.31.52.63.74.80] <-> <0.0.0.0:0>:[00.00.00.00.00.00]. flg[1]
15:05:37.402627 [INFO] Conn[000f]: Set state 'DeallocReq'->'Idle'
15:05:37.413459 [INFO] PBXIPC-SIP. RX. rel-cplt
15:05:37.413518 [INFO] # callref 0427
15:05:37.413559 [INFO] # cause 487
15:05:37.414438 [INFO] SIP. Callref 0427. Release complete
15:05:37.414503 [INFO] SIP. Callref 0427. New state 'SIPT_IDLE'
15:05:37.414556 [INFO] Port SIPT:0427. Release Complete, cause 'Normal call clearing', dcl '0', loc '0'
15:05:37.414609 [INFO] Port SIPT:0427. Save CDR. disabled. [0x0]
15:05:37.414668 [INFO] Port SIPT:0427. Set state 'Ready'
15:05:37.426527 [INFO] Q931. Line 00/00. Call AEAA. RX 5
DUMP: 08.02.2E.AA.5A.
0x2EAA (from orig), MSG=RELEASE COMPLETE:
---------------------------------
15:05:37.426597 [INFO] Q931. Line 00/00. Call AEAA. Recv 'Release complete'
15:05:37.426643 [INFO] Port PRI:00:00. Release Complete, cause 'Normal, unspecified', dcl '0', loc '1'
15:05:37.426692 [INFO] Port PRI:00:00. Save CDR. disabled. [0x0]
15:05:37.426748 [INFO] Port PRI:00:00. Set state 'Ready'
15:05:37.426790 [INFO] Q931. Line 00/00. Call AEAA. State 'Null'
SMG-4. SN: VI3F000195 Software Version: V.3.1.2.1101. 4/S Build: Nov 18 2015 09:51:54
Log stopped at: 15:05:45.616726

pbx_sip

2016-02-19 15:04:31.580 app.c !Eltex pa_sip 3.1.1.51. Log started
2016-02-19 15:04:31.580 app.c set log_level 5
2016-02-19 15:04:31.580 ipc.c pbx-ipc SIP: TX (005)
2016-02-19 15:04:31.581 ipc.c 15 23 01 00 05 .#...
2016-02-19 15:04:31.581 ipc.c PBXIPC-SIP. TX. trace
2016-02-19 15:04:31.581 ipc.c # trace-level [5]
2016-02-19 15:04:42.020 tsx0x30ead4 !Timeout timer event
2016-02-19 15:04:42.020 tsx0x30ead4 State changed from Completed to Terminated, event=TIMER
2016-02-19 15:04:42.020 tsx0x30ead4 Timeout timer event
2016-02-19 15:04:42.020 tsx0x30ead4 State changed from Terminated to Destroyed, event=TIMER
2016-02-19 15:04:42.020 tdta0x31b2e8 Destroying txdata Response msg 200/OPTIONS/cseq=102 (tdta0x31b2e8)
2016-02-19 15:04:42.020 tsx0x30ead4 Transaction destroyed!
2016-02-19 15:05:09.880 sip_endpoint.c !Processing incoming message: Request msg OPTIONS/cseq=102 (rdata0x31f99c)
2016-02-19 15:05:09.881 tsx0x30ead4 Transaction created for Request msg OPTIONS/cseq=102 (rdata0x31f99c)
2016-02-19 15:05:09.881 tsx0x30ead4 Incoming Request msg OPTIONS/cseq=102 (rdata0x31f99c) in state Null
2016-02-19 15:05:09.881 tsx0x30ead4 State changed from Null to Trying, event=RX_MSG
2016-02-19 15:05:09.881 endpoint Response msg 200/OPTIONS/cseq=102 (tdta0x31b2e8) created
2016-02-19 15:05:09.881 ipc.c pbx-ipc SIP: TX (029)
2016-02-19 15:05:09.881 ipc.c 0F 21 02 00 DE 00 03 02 00 01 00 22 0A 00 31 30 .!........."..10
2016-02-19 15:05:09.881 ipc.c 2E 30 2E 30 2E 31 30 33 05 02 00 C4 13 .0.0.103.....
2016-02-19 15:05:09.881 ipc.c PBXIPC-SIP. TX. keep-alive-req
2016-02-19 15:05:09.881 ipc.c # requestID 00de
2016-02-19 15:05:09.881 ipc.c # trunkID 01
2016-02-19 15:05:09.881 ipc.c # Hostname '10.0.0.103'
2016-02-19 15:05:09.881 ipc.c # port 5060
2016-02-19 15:05:09.882 ipc.c !pbx-ipc SIP: RX (204)
2016-02-19 15:05:09.882 ipc.c 10 21 02 00 DE 00 03 02 00 01 00 0D B9 00 76 3D .!............v=
2016-02-19 15:05:09.882 ipc.c 30 0D 0A 6F 3D 20 30 20 30 20 49 4E 20 49 50 34 0..o= 0 0 IN IP4
2016-02-19 15:05:09.882 ipc.c 20 31 30 2E 30 2E 30 2E 32 38 0D 0A 73 3D 2D 0D 10.0.0.28..s=-.
2016-02-19 15:05:09.882 ipc.c 0A 63 3D 49 4E 20 49 50 34 20 31 30 2E 30 2E 30 .c=IN IP4 10.0.0
2016-02-19 15:05:09.882 ipc.c 2E 32 38 0D 0A 74 3D 30 20 30 0D 0A 6D 3D 61 75 .28..t=0 0..m=au
2016-02-19 15:05:09.882 ipc.c 64 69 6F 20 30 20 52 54 50 2F 41 56 50 20 38 20 dio 0 RTP/AVP 8
2016-02-19 15:05:09.882 ipc.c 30 20 31 30 31 0D 0A 61 3D 72 74 70 6D 61 70 3A 0 101..a=rtpmap:
2016-02-19 15:05:09.882 ipc.c 38 20 50 43 4D 41 2F 38 30 30 30 0D 0A 61 3D 72 8 PCMA/8000..a=r
2016-02-19 15:05:09.882 ipc.c 74 70 6D 61 70 3A 30 20 50 43 4D 55 2F 38 30 30 tpmap:0 PCMU/800
2016-02-19 15:05:09.882 ipc.c 30 0D 0A 61 3D 72 74 70 6D 61 70 3A 31 30 31 20 0..a=rtpmap:101
2016-02-19 15:05:09.882 ipc.c 74 65 6C 65 70 68 6F 6E 65 2D 65 76 65 6E 74 2F telephone-event/
2016-02-19 15:05:09.882 ipc.c 38 30 30 30 0D 0A 61 3D 66 6D 74 70 3A 31 30 31 8000..a=fmtp:101
2016-02-19 15:05:09.882 ipc.c 20 30 2D 31 35 0D 0A 0F 02 00 C8 00 0-15.......
2016-02-19 15:05:09.882 ipc.c PBXIPC-SIP. RX. keep-alive-rsp
2016-02-19 15:05:09.883 ipc.c # requestID 00de
2016-02-19 15:05:09.883 ipc.c # trunkID 01
2016-02-19 15:05:09.883 ipc.c # SDP len (185)
2016-02-19 15:05:09.883 ipc.c # cause 200
2016-02-19 15:05:09.890 ipc_msg.c !ipc_msg_parse: msg type = keep-alive-rsp [16]
2016-02-19 15:05:09.890 ipc_msg.c get_ie: ie [33][request-id] size [2]
2016-02-19 15:05:09.890 ipc_msg.c get_ie: ie [3][trunk-id] size [2]
2016-02-19 15:05:09.890 ipc_msg.c get_ie: ie [13][sdp] size [185]
2016-02-19 15:05:09.890 ipc_msg.c get_ie: ie [15][cause] size [2]
2016-02-19 15:05:09.890 ipc.c ipc_process: msg ptr = 0x30f278. type [16]
2016-02-19 15:05:09.890 mod_pa_pjsip.c keep_alive_reply: cause = 200
2016-02-19 15:05:09.890 tsx0x30ead4 Sending Response msg 200/OPTIONS/cseq=102 (tdta0x31b2e8) in state Trying
2016-02-19 15:05:09.891 sip_resolve.c Target '10.0.0.103:5060' type=UDP resolved to '10.0.0.103:5060' type=UDP (UDP transport)
2016-02-19 15:05:09.891 tsx0x30ead4 State changed from Trying to Completed, event=TX_MSG
2016-02-19 15:05:34.319 ipc.c !pbx-ipc SIP: RX (317)
2016-02-19 15:05:34.319 ipc.c 01 01 02 00 27 04 03 02 00 01 00 22 0A 00 31 30 ....'......"..10
2016-02-19 15:05:34.320 ipc.c 2E 30 2E 30 2E 31 30 33 05 02 00 C4 13 08 2F 00 .0.0.103....../.
2016-02-19 15:05:34.320 ipc.c 01 01 00 00 02 00 00 00 00 00 00 07 00 00 00 35 ...............5
2016-02-19 15:05:34.320 ipc.c 33 39 39 34 34 34 00 00 00 00 00 00 00 00 00 00 399444..........
2016-02-19 15:05:34.320 ipc.c 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0D ................
2016-02-19 15:05:34.320 ipc.c EB 00 76 3D 30 0D 0A 6F 3D 6D 67 61 70 70 20 31 ..v=0..o=mgapp 1
2016-02-19 15:05:34.320 ipc.c 34 34 30 33 30 30 32 32 35 20 36 32 35 39 33 31 440300225 625931
2016-02-19 15:05:34.320 ipc.c 39 33 37 20 49 4E 20 49 50 34 20 31 30 2E 30 2E 937 IN IP4 10.0.
2016-02-19 15:05:34.320 ipc.c 30 2E 32 38 0D 0A 73 3D 2D 0D 0A 63 3D 49 4E 20 0.28..s=-..c=IN
2016-02-19 15:05:34.320 ipc.c 49 50 34 20 31 30 2E 30 2E 30 2E 32 38 0D 0A 74 IP4 10.0.0.28..t
2016-02-19 15:05:34.320 ipc.c 3D 30 20 30 0D 0A 6D 3D 61 75 64 69 6F 20 31 30 =0 0..m=audio 10
2016-02-19 15:05:34.320 ipc.c 30 33 36 20 52 54 50 2F 41 56 50 20 38 20 30 20 036 RTP/AVP 8 0
2016-02-19 15:05:34.320 ipc.c 31 30 31 0D 0A 61 3D 72 74 70 6D 61 70 3A 38 20 101..a=rtpmap:8
2016-02-19 15:05:34.320 ipc.c 50 43 4D 41 2F 38 30 30 30 0D 0A 61 3D 72 74 70 PCMA/8000..a=rtp
2016-02-19 15:05:34.320 ipc.c 6D 61 70 3A 30 20 50 43 4D 55 2F 38 30 30 30 0D map:0 PCMU/8000.
2016-02-19 15:05:34.320 ipc.c 0A 61 3D 72 74 70 6D 61 70 3A 31 30 31 20 74 65 .a=rtpmap:101 te
2016-02-19 15:05:34.320 ipc.c 6C 65 70 68 6F 6E 65 2D 65 76 65 6E 74 2F 38 30 lephone-event/80
2016-02-19 15:05:34.320 ipc.c 30 30 0D 0A 61 3D 66 6D 74 70 3A 31 30 31 20 30 00..a=fmtp:101 0
2016-02-19 15:05:34.320 ipc.c 2D 31 35 0D 0A 61 3D 70 74 69 6D 65 3A 32 30 0D -15..a=ptime:20.
2016-02-19 15:05:34.320 ipc.c 0A 61 3D 73 65 6E 64 72 65 63 76 0D 0A .a=sendrecv..
2016-02-19 15:05:34.320 ipc.c PBXIPC-SIP. RX. seize
2016-02-19 15:05:34.320 ipc.c # callref 0427
2016-02-19 15:05:34.320 ipc.c # trunkID 01
2016-02-19 15:05:34.320 ipc.c # Hostname '10.0.0.103'
2016-02-19 15:05:34.320 ipc.c # port 5060
2016-02-19 15:05:34.320 ipc.c # cdpn <5399444> (7) cat 0x00
2016-02-19 15:05:34.320 ipc.c # SDP len (235)
2016-02-19 15:05:34.320 ipc_msg.c !ipc_msg_parse: msg type = seize [1]
2016-02-19 15:05:34.321 ipc_msg.c get_ie: ie [1][callref] size [2]
2016-02-19 15:05:34.321 ipc_msg.c get_ie: ie [3][trunk-id] size [2]
2016-02-19 15:05:34.321 ipc_msg.c get_ie: ie [34][hostname] size [10]
2016-02-19 15:05:34.321 ipc_msg.c get_ie: ie [5][port] size [2]
2016-02-19 15:05:34.321 ipc_msg.c get_ie: ie [8][cdpn] size [47]
2016-02-19 15:05:34.321 ipc_msg.c get_ie: ie [13][sdp] size [235]
2016-02-19 15:05:34.321 ipc.c ipc_process: msg ptr = 0x30f278. type [1]
2016-02-19 15:05:34.321 call.c call_seize: call 0427. try acquire. dest: <10.0.0.103:5060>
2016-02-19 15:05:34.321 call.c call_seize: call 0427. sdp [235] <0x30fad8>
2016-02-19 15:05:34.321 call.c call_seize: call 0427 CgPN is not set
2016-02-19 15:05:34.321 call.c call_seize: call 0427. try make call
2016-02-19 15:05:34.321 call.c call_seize: call 0427. Encapsulate ISUP: 'NO'
2016-02-19 15:05:34.321 dlg0x319ebc UAC dialog created
2016-02-19 15:05:34.321 call.c make_call: call 0427.

R-URI <sip:5399444@10.0.0.103:5060>
From "Anonymous" <sip:anonymous@anonymous.invalid:5060>
To <sip:5399444@10.0.0.103:5060>
Contact <sip:10.0.0.28:5060>

2016-02-19 15:05:34.321 call.c make_call: call 0427. sdp [235] <0x31e3ac>

v=0
o=mgapp 1440300225 625931937 IN IP4 10.0.0.28
s=-
c=IN IP4 10.0.0.28
t=0 0
m=audio 10036 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv

2016-02-19 15:05:34.321 call.c make_call: call 0427. Option for call:, use timer, support timer
2016-02-19 15:05:34.321 dlg0x319ebc Module mod-invite added as dialog usage, data=0x1f520c
2016-02-19 15:05:34.322 dlg0x319ebc Session count inc to 2 by mod-invite
2016-02-19 15:05:34.322 dlg0x319ebc Module mod-100rel added as dialog usage, data=0x30e5a4
2016-02-19 15:05:34.322 dlg0x319ebc 100rel module attached
2016-02-19 15:05:34.322 inv0x319ebc UAC invite session created for dialog dlg0x319ebc
2016-02-19 15:05:34.322 endpoint Request msg INVITE/cseq=5143 (tdta0x30ffb8) created.
2016-02-19 15:05:34.322 call.c make_call: call 0427. call <0x404d3fec> inv <0x1f520c> dlg <0x319ebc>
2016-02-19 15:05:34.322 call.c call_fill_supported_hdr: call 0427. Add 'timer' into supported header
2016-02-19 15:05:34.322 call.c call_add_supported_hdr: call 0427. Add supported header
2016-02-19 15:05:34.322 inv0x319ebc Sending Request msg INVITE/cseq=5143 (tdta0x30ffb8)
2016-02-19 15:05:34.322 dlg0x319ebc Sending Request msg INVITE/cseq=5143 (tdta0x30ffb8)
2016-02-19 15:05:34.322 tsx0x311fcc Transaction created for Request msg INVITE/cseq=5142 (tdta0x30ffb8)
2016-02-19 15:05:34.322 tsx0x311fcc Sending Request msg INVITE/cseq=5142 (tdta0x30ffb8) in state Null
2016-02-19 15:05:34.322 sip_resolve.c Target '10.0.0.103:5060' type=Unspecified resolved to '10.0.0.103:5060' type=UDP (UDP transport)
2016-02-19 15:05:34.323 tsx0x311fcc State changed from Null to Calling, event=TX_MSG
2016-02-19 15:05:34.323 dlg0x319ebc Transaction tsx0x311fcc state changed to Calling
2016-02-19 15:05:34.323 call.c call_on_state_changed: call 0427. changed to CALLING state with event TSX_STATE
2016-02-19 15:05:34.323 call.c call_on_tsx_state_changed: call 0427. tsx 'tsx0x311fcc', role UAC, method INVITE, event TX_MSG, tsx-state: Calling
2016-02-19 15:05:34.323 call.c call_on_tsx_state_changed: call 0427. INVITE UAC. status code [0]
2016-02-19 15:05:34.323 call.c call_on_tsx_state_changed: call 0427. Unsupported status code 0 for not-answered call
2016-02-19 15:05:34.324 sip_endpoint.c !Processing incoming message: Response msg 401/INVITE/cseq=5142 (rdata0x31f99c)
2016-02-19 15:05:34.324 tsx0x311fcc Incoming Response msg 401/INVITE/cseq=5142 (rdata0x31f99c) in state Calling
2016-02-19 15:05:34.324 endpoint Request msg ACK/cseq=5142 (tdta0x3146b8) created.
2016-02-19 15:05:34.324 tsx0x311fcc State changed from Calling to Completed, event=RX_MSG
2016-02-19 15:05:34.324 dlg0x319ebc Received Response msg 401/INVITE/cseq=5142 (rdata0x31f99c)
2016-02-19 15:05:34.324 dlg0x319ebc Transaction tsx0x311fcc state changed to Completed
2016-02-19 15:05:34.324 inv0x319ebc Sending Request msg INVITE/cseq=5142 (tdta0x30ffb8)
2016-02-19 15:05:34.324 dlg0x319ebc Sending Request msg INVITE/cseq=5142 (tdta0x30ffb8)
2016-02-19 15:05:34.324 tsx0x31766c Transaction created for Request msg INVITE/cseq=5143 (tdta0x30ffb8)
2016-02-19 15:05:34.325 tsx0x31766c Sending Request msg INVITE/cseq=5143 (tdta0x30ffb8) in state Null
2016-02-19 15:05:34.325 endpoint Request msg INVITE/cseq=5143 (tdta0x30ffb8): skipping target resolution because address is already set
2016-02-19 15:05:34.325 tsx0x31766c State changed from Null to Calling, event=TX_MSG
2016-02-19 15:05:34.325 dlg0x319ebc Transaction tsx0x31766c state changed to Calling
2016-02-19 15:05:34.325 call.c call_on_tsx_state_changed: call 0427. tsx 'tsx0x31766c', role UAC, method INVITE, event TX_MSG, tsx-state: Calling
2016-02-19 15:05:34.325 call.c call_on_tsx_state_changed: call 0427. INVITE UAC. status code [0]
2016-02-19 15:05:34.325 call.c call_on_tsx_state_changed: call 0427. Unsupported status code 0 for not-answered call
2016-02-19 15:05:34.325 call.c call_on_tsx_state_changed: call 0427. tsx 'tsx0x311fcc', role UAC, method INVITE, event RX_MSG, tsx-state: Completed
2016-02-19 15:05:34.325 call.c call_check_isup: call 0427. checking for ISUP presence
2016-02-19 15:05:34.325 call.c call_check_isup: call 0427. ISUP message not found
2016-02-19 15:05:34.325 call.c call_on_tsx_state_changed: call 0427. INVITE UAC. status code [401]
2016-02-19 15:05:34.325 call.c call_on_tsx_state_changed: call 0427. Unsupported status code 401 for not-answered call
2016-02-19 15:05:34.351 sip_endpoint.c !Processing incoming message: Response msg 100/INVITE/cseq=5143 (rdata0x31f99c)
2016-02-19 15:05:34.351 tsx0x31766c Incoming Response msg 100/INVITE/cseq=5143 (rdata0x31f99c) in state Calling
2016-02-19 15:05:34.351 tsx0x31766c State changed from Calling to Proceeding, event=RX_MSG
2016-02-19 15:05:34.351 dlg0x319ebc Received Response msg 100/INVITE/cseq=5143 (rdata0x31f99c)
2016-02-19 15:05:34.351 dlg0x319ebc Transaction tsx0x31766c state changed to Proceeding
2016-02-19 15:05:34.351 call.c call_on_tsx_state_changed: call 0427. tsx 'tsx0x31766c', role UAC, method INVITE, event RX_MSG, tsx-state: Proceeding
2016-02-19 15:05:34.351 call.c call_check_isup: call 0427. checking for ISUP presence
2016-02-19 15:05:34.351 call.c call_check_isup: call 0427. ISUP message not found
2016-02-19 15:05:34.351 call.c call_on_tsx_state_changed: call 0427. INVITE UAC. status code [100]
2016-02-19 15:05:34.351 call.c call_on_tsx_state_changed: call 0427. Unsupported status code 100 for not-answered call
2016-02-19 15:05:34.720 sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=5143 (rdata0x31f99c)
2016-02-19 15:05:34.720 tsx0x31766c Incoming Response msg 180/INVITE/cseq=5143 (rdata0x31f99c) in state Proceeding
2016-02-19 15:05:34.720 tsx0x31766c State changed from Proceeding to Proceeding, event=RX_MSG
2016-02-19 15:05:34.720 dlg0x319ebc Received Response msg 180/INVITE/cseq=5143 (rdata0x31f99c)
2016-02-19 15:05:34.720 dlg0x319ebc Route-set updated
2016-02-19 15:05:34.720 dlg0x319ebc Transaction tsx0x31766c state changed to Proceeding
2016-02-19 15:05:34.720 call.c call_on_state_changed: call 0427. changed to EARLY state with event TSX_STATE
2016-02-19 15:05:34.720 call.c call 0427. transport proto: UDP
2016-02-19 15:05:34.720 call.c call_on_tsx_state_changed: call 0427. tsx 'tsx0x31766c', role UAC, method INVITE, event RX_MSG, tsx-state: Proceeding
2016-02-19 15:05:34.720 call.c call_check_isup: call 0427. checking for ISUP presence
2016-02-19 15:05:34.720 call.c call_check_isup: call 0427. ISUP message not found
2016-02-19 15:05:34.720 call.c call_on_tsx_state_changed: call 0427. INVITE UAC. status code [180]
2016-02-19 15:05:34.720 ipc.c pbx-ipc SIP: TX (049)
2016-02-19 15:05:34.720 ipc.c 05 01 02 00 27 04 0F 02 00 B4 00 24 20 00 63 53 ....'......$ .cS
2016-02-19 15:05:34.720 ipc.c 54 2D 35 6A 4E 74 77 36 41 7A 6B 38 74 37 77 54 T-5jNtw6Azk8t7wT
2016-02-19 15:05:34.721 ipc.c 6F 5A 6F 57 42 49 39 57 41 38 54 6E 50 76 11 00 oZoWBI9WA8TnPv..
2016-02-19 15:05:34.721 ipc.c 00 .
2016-02-19 15:05:34.721 ipc.c PBXIPC-SIP. TX. answer
2016-02-19 15:05:34.721 ipc.c # callref 0427
2016-02-19 15:05:34.721 ipc.c # cause 180
2016-02-19 15:05:34.721 ipc.c # Call-ID len (32)
2016-02-19 15:05:34.721 ipc.c # Display name ''
2016-02-19 15:05:37.401 ipc.c !pbx-ipc SIP: RX (016)
2016-02-19 15:05:37.401 ipc.c 06 01 02 00 27 04 28 02 00 10 00 0F 02 00 C8 00 ....'.(.........
2016-02-19 15:05:37.401 ipc.c PBXIPC-SIP. RX. rel-req
2016-02-19 15:05:37.401 ipc.c # callref 0427
2016-02-19 15:05:37.401 ipc.c # q850-cause 16
2016-02-19 15:05:37.401 ipc.c # cause 200
2016-02-19 15:05:37.410 ipc_msg.c !ipc_msg_parse: msg type = rel-req [6]
2016-02-19 15:05:37.410 ipc_msg.c get_ie: ie [1][callref] size [2]
2016-02-19 15:05:37.410 ipc_msg.c get_ie: ie [40][q850-cause] size [2]
2016-02-19 15:05:37.410 ipc_msg.c get_ie: ie [15][cause] size [2]
2016-02-19 15:05:37.410 ipc.c ipc_process: msg ptr = 0x319598. type [6]
2016-02-19 15:05:37.410 call.c call_release_req: call 0427. release req w/cause 200 q850-cause: 16
2016-02-19 15:05:37.410 call.c call_end_session: call 0427. End session with response 200 (q850-cause: 16)
2016-02-19 15:05:37.410 inv0x319ebc End session in state 'early' with code 200 (terminate pending)
2016-02-19 15:05:37.411 endpoint Request msg CANCEL/cseq=5143 (tdta0x317e10) created.
2016-02-19 15:05:37.411 call.c add_isup_rel_reason_header: call 0427. Adding Reason header: "Q.850;cause=16;text="Normal call clearing""
2016-02-19 15:05:37.411 inv0x319ebc Sending Request msg CANCEL/cseq=5143 (tdta0x317e10)
2016-02-19 15:05:37.411 dlg0x319ebc Sending Request msg CANCEL/cseq=5143 (tdta0x317e10)
2016-02-19 15:05:37.411 tsx0x321944 Transaction created for Request msg CANCEL/cseq=5143 (tdta0x317e10)
2016-02-19 15:05:37.411 tsx0x321944 Sending Request msg CANCEL/cseq=5143 (tdta0x317e10) in state Null
2016-02-19 15:05:37.411 endpoint Request msg CANCEL/cseq=5143 (tdta0x317e10): skipping target resolution because address is already set
2016-02-19 15:05:37.411 tsx0x321944 State changed from Null to Calling, event=TX_MSG
2016-02-19 15:05:37.411 dlg0x319ebc Transaction tsx0x321944 state changed to Calling
2016-02-19 15:05:37.411 call.c call_on_tsx_state_changed: call 0427. tsx 'tsx0x321944', role UAC, method CANCEL, event TX_MSG, tsx-state: Calling
2016-02-19 15:05:37.412 sip_endpoint.c !Processing incoming message: Response msg 487/INVITE/cseq=5143 (rdata0x31f99c)
2016-02-19 15:05:37.412 tsx0x31766c Incoming Response msg 487/INVITE/cseq=5143 (rdata0x31f99c) in state Proceeding
2016-02-19 15:05:37.412 endpoint Request msg ACK/cseq=5143 (tdta0x324030) created.
2016-02-19 15:05:37.412 tsx0x31766c State changed from Proceeding to Completed, event=RX_MSG
2016-02-19 15:05:37.412 dlg0x319ebc Received Response msg 487/INVITE/cseq=5143 (rdata0x31f99c)
2016-02-19 15:05:37.413 dlg0x319ebc Transaction tsx0x31766c state changed to Completed
2016-02-19 15:05:37.413 call.c call_on_state_changed: call 0427. changed to DISCONNCTD state with event TSX_STATE
2016-02-19 15:05:37.413 call.c call_state_disconnected: call 0427. Disconnected. Event type TSX_STATE with response 487
2016-02-19 15:05:37.413 call.c call_check_isup: call 0427. checking for ISUP presence
2016-02-19 15:05:37.413 call.c call_check_isup: call 0427. ISUP message not found
2016-02-19 15:05:37.413 ipc.c pbx-ipc SIP: TX (011)
2016-02-19 15:05:37.413 ipc.c 07 01 02 00 27 04 0F 02 00 E7 01 ....'......
2016-02-19 15:05:37.413 ipc.c PBXIPC-SIP. TX. rel-cplt
2016-02-19 15:05:37.413 ipc.c # callref 0427
2016-02-19 15:05:37.413 ipc.c # cause 487
2016-02-19 15:05:37.413 dlg0x319ebc Session count dec to 1 by mod-invite
2016-02-19 15:05:37.413 call.c call_on_tsx_state_changed: inv <0x1f520c>, mod-data <(nil)>
2016-02-19 15:05:37.413 tdta0x30ffb8 Destroying txdata Request msg INVITE/cseq=5143 (tdta0x30ffb8)
2016-02-19 15:05:37.413 sip_endpoint.c Processing incoming message: Response msg 200/CANCEL/cseq=5143 (rdata0x312784)
2016-02-19 15:05:37.414 tsx0x321944 Incoming Response msg 200/CANCEL/cseq=5143 (rdata0x312784) in state Calling
2016-02-19 15:05:37.414 tsx0x321944 State changed from Calling to Completed, event=RX_MSG
2016-02-19 15:05:37.414 dlg0x319ebc Received Response msg 200/CANCEL/cseq=5143 (rdata0x312784)
2016-02-19 15:05:37.414 dlg0x319ebc Transaction tsx0x321944 state changed to Completed
2016-02-19 15:05:41.920 tsx0x30ead4 !Timeout timer event
2016-02-19 15:05:41.920 tsx0x30ead4 State changed from Completed to Terminated, event=TIMER
2016-02-19 15:05:41.920 tsx0x30ead4 Timeout timer event
2016-02-19 15:05:41.920 tsx0x30ead4 State changed from Terminated to Destroyed, event=TIMER
2016-02-19 15:05:41.920 tdta0x31b2e8 Destroying txdata Response msg 200/OPTIONS/cseq=102 (tdta0x31b2e8)
2016-02-19 15:05:41.920 tsx0x30ead4 Transaction destroyed!
2016-02-19 15:05:42.460 tsx0x321944 Timeout timer event
2016-02-19 15:05:42.460 tsx0x321944 State changed from Completed to Terminated, event=TIMER
2016-02-19 15:05:42.460 dlg0x319ebc Transaction tsx0x321944 state changed to Terminated
2016-02-19 15:05:42.460 call.c call_on_tsx_state_changed: inv <0x1f520c>, mod-data <(nil)>
2016-02-19 15:05:42.460 tsx0x321944 Timeout timer event
2016-02-19 15:05:42.460 tsx0x321944 State changed from Terminated to Destroyed, event=TIMER
2016-02-19 15:05:42.461 tdta0x317e10 Destroying txdata Request msg CANCEL/cseq=5143 (tdta0x317e10)
2016-02-19 15:05:42.461 tsx0x321944 Transaction destroyed!
2016-02-19 15:05:48.848 ipc.c !pbx-ipc SIP: RX (005)
2016-02-19 15:05:48.848 ipc.c 15 23 01 00 00 .#...
2016-02-19 15:05:48.848 ipc.c PBXIPC-SIP. RX. trace
2016-02-19 15:05:48.848 ipc.c # trace-level [0]
2016-02-19 15:05:48.870 ipc_msg.c !ipc_msg_parse: msg type = trace [21]
2016-02-19 15:05:48.870 ipc_msg.c get_ie: ie [35][trace-level] size [1]
2016-02-19 15:05:48.870 ipc.c ipc_process: msg ptr = 0x319598. type [21]
2016-02-19 15:05:48.870 app.c set log_level 0


pbx_siperr

2016-02-19 15:04:31.580 app.c !Eltex pa_sip 3.1.1.51. Log started
2016-02-19 15:04:31.580 app.c set log_level 5
2016-02-19 15:05:48.870 app.c set log_level 0

[Женя]

узнавайте у провайдера почему они рубят звонок, вот он них отбой по q931:

Код: Выделить всё

15:05:37.399144 [INFO] Q931. Line 00/00. Call AEAA. RX 9
DUMP:   08.02.2E.AA.45.08.02.81.90.
0x2EAA (from orig), MSG=DISCONNECT:
[cause: Normal call clearing (location=private network serving local user, std=CCITT)]

причем, судя по cause, это нормальный отбой. как будто абонент А просто положил трубку