CAPI - B3count is full, dropping packet

[nielsd]

Hallo,

nun bin ich doch mal wieder hier, denn zu o.g. Fehlermeldung finde ich nichts wirklich hilfreiches - auch die Quellen von chan_capi (soweit ich diese lesen kann) bringen mich nicht wirklich zu einer Lösung.

Bei Telefonaten von/zum ISDN Festnetz (3x ISDN Basisanschluß über einen vom Telco bereitgestellten "Pegasus") per lokalem VoIP Telefon (Linksys SPA 922) kommt es bei bestimmten Zielen nach ca. 10 Sekunden laufenden Telefonates zu folgender Meldung (aus capi):

CAPI - B3count is full, dropping packet

Ich betreibe Linksys SPA 922 an einem Intel-Atom CPU N270 (1,6 GHz) mit 1 GB RAM.

Als ISDN Interface verwende ich eine Dialogic Diva UM-4BRI-8 PCI v2 - SerNo:13796.

Als Treiber kommen die offiziellen von Dialogic zum Einsatz - so auch die dort mitgelieferte chan_capi (aktuellstes Paket).

hier meine chan_capi:

[ISDN1]
ntmode=no
isdnmode=did
incomingmsn=* ;Use Diva MSN settings
group=1
callgroup=1
pickupgroup=1
transfergroup=1
controller=1
softdtmf=off
relaxdtmf=off
faxdetect=off
faxdetecttime=0
accountcode=
context=from-pstn
holdtype=local
echocancelold=no
bridge=yes
devices=2
echocancel=yes
echocancelnlp=1
disallow=all
allow=alaw

[ISDN2]
ntmode=no
isdnmode=did
incomingmsn=* ;Use Diva MSN settings
group=1
callgroup=1
pickupgroup=1
transfergroup=1
controller=2
softdtmf=off
relaxdtmf=off
faxdetect=off
faxdetecttime=0
accountcode=
context=from-pstn
holdtype=local
echocancelold=no
bridge=yes
devices=2
echocancel=yes
echocancelnlp=1
disallow=all
allow=alaw

[ISDN3]
ntmode=no
isdnmode=did
incomingmsn=* ;Use Diva MSN settings
group=1
callgroup=1
pickupgroup=1
transfergroup=1
controller=3
softdtmf=off
relaxdtmf=off
faxdetect=off
faxdetecttime=0
accountcode=
context=from-pstn
holdtype=local
echocancelold=no
bridge=yes
devices=2
echocancel=yes
echocancelnlp=1
disallow=all
allow=alaw

[ISDN4]
ntmode=yes
isdnmode=did
incomingmsn=* ;Use Diva MSN settings
group=4
callgroup=4
pickupgroup=4
transfergroup=4
controller=4
softdtmf=off
relaxdtmf=off
faxdetect=off
faxdetecttime=0
accountcode=
context=from-internal
;context=from-isdn-4
holdtype=local
echocancelold=no
bridge=no
devices=2
echocancel=no
echocancelnlp=1
disallow=all
allow=alaw

[pbx1 asterisk]# cat /var/log/diva1.log 
INITIAL XLOG:  CARD:1, Dialogic Diva UM-4BRI-8 PCI v2 SN:13796 - PORT 1, STARTED AT: Fr 22. Okt 13:53:41 CEST 2010
Product Build: product/linux/source.9.5 110-91 
Package Build: opendiva/rpm.9.5/source 110-95 

    0:0040:997 - Instance(0)=0x8037a000 image_start=0x80000000, shared_memory=0x80001000 card=88
    0:0000:000 - Diva Server UM-4BRI-8M 2.0 (2620)
    0:0000:000 - Protocol: 'TE_DMLT, Build 110-19, Protocol 6.03(V22) 110-1 [F#03FF]'
    0:0000:000 - DSP task 6: DIVA Server BRI 2M Kernel Version 1.00 Build 110-846
    0:0000:000 - DSP task 15: DIVA Server BRI 2M SoftIP Kernel Version 1.00 Build 110-846
    0:0000:000 - DSP task 100: HSCX Task Version 1.00 Build 110-846
    0:0000:000 - DSP task 104: HSCXBR Task Version 1.00 Build 110-846
    0:0000:001 - DSP task 107: HSCX Small Task Version 1.00 Build 110-846
    0:0000:001 - DSP task 110: PIAFSD Task Version 1.00 Build 110-846
    0:0000:001 - DSP task 200: V.110 Kernel Task Version 1.00 Build 110-846
    0:0000:001 - DSP task 201: V.110 Overlay (600) Version 1.00 Build 110-846
    0:0000:001 - DSP task 202: V.110 Overlay (1200) Version 1.00 Build 110-846
    0:0000:001 - DSP task 203: V.110 Overlay (1200/75) Version 1.00 Build 110-846
    0:0000:001 - DSP task 204: V.110 Overlay (75/1200) Version 1.00 Build 110-846
    0:0000:001 - DSP task 205: V.110 Overlay (2400) Version 1.00 Build 110-846
    0:0000:001 - DSP task 206: V.110 Overlay (4800,9600,19200,38400) Version 1.00 Build 110-846
    0:0000:001 - DSP task 207: V.110 Overlay (7200,14400,28800) Version 1.00 Build 110-846
    0:0000:001 - DSP task 208: V.110 Overlay (12000,24000) Version 1.00 Build 110-846
    0:0000:001 - DSP task 209: V.110 Overlay (48000) Version 1.00 Build 110-846
    0:0000:001 - DSP task 210: V.110 Overlay (56000) Version 1.00 Build 110-846
    0:0000:001 - DSP task 225: V.110 Kernel Task BRI 2M Version 1.00 Build 110-846
    0:0000:001 - DSP task 504: VOICEBR Task Version 1.00 Build 110-846
    0:0000:001 - DSP task 510: DTMF Task Version 1.00 Build 110-846
    0:0000:001 - DSP task 512: DTMFBR Task Version 1.00 Build 110-846
    0:0000:001 - DSP task 520: SIG.MDM Task Version 1.00 Build 110-846
    0:0000:001 - DSP task 532: TONEBR Task Version 1.00 Build 110-846
    0:0000:001 - DSP task 542: MEASBR Task Version 1.00 Build 110-846
    0:0000:001 - DSP task 552: LECBR Task Version 1.00 Build 110-846
    0:0000:001 - DSP task 590: Conferencing Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 624: SIG Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 604: FSK OWN Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 607: V8.F34 Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 608: INFO Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 609: V.34 Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 622: INFOH.F34 Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 623: HV34.F34 Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 610: DIAL/FSK/FAX.F34 Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 611: DIAL.F34 Partial Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 612: FSKFAX.F34 Partial Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 613: FAX.F34 Partial Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 614: V.22/V.32 LEC Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 615: V.32 Partial Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 618: V.90 DPCM Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 619: V.90 APCM Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 625: V.22FC Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 629: V.22bis FC Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 627: V.29FC Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 620: V.18 OWN-LK Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 621: V.OWN Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 650: TIKRNL81.F34 Task Version 1.00 Build 110-846
    0:0000:001 - DSP task 702: VKRNLBR.SEC Task Version 1.00 Build 110-846
    0:0000:001 - DSP task 716: VKRNLSB.SEC Task Version 1.00 Build 110-846
    0:0000:001 - DSP task 709: VKRNL Small Task Version 1.00 Build 110-846
    0:0000:001 - DSP task 703: G.711 Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 704: RTP G.711/G.726 Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 706: RTP GSM Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 711: RTP G.729AB Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 722: CKRNLBR.SEC Task Version 1.00 Build 110-846
    0:0000:001 - DSP task 725: CKRNLSB.SEC Task Version 1.00 Build 110-846
    0:0000:001 - DSP task 712: VHook LEC.SEC Overlay Version 1.00 Build 110-846
    0:0000:001 - DSP task 713: VHook SIG.SEC Overlay Version 1.00 Build 110-846
    0:0000:002 - Conf: DLI21st=1,MWIREG=1,ECTA=1,ECTF=1
    0:0000:002 - Conf: S2=1,Tei=1,NT2=1,Perm=0,WDog=0,LowCh=0,L1Hunt=0x0
    0:0000:002 - Conf: Loop=0,DidLen=2,Law=0,nosig=0,AlertTO=0xffff,PDisc=0
    0:0000:002 - Conf: Prot=1,PVer=0,NT=0,Lim=0,RTone=0,L2_Links=1
    0:0000:002 - Conf: XConn=0/6,ClkM=1/128/4096,ClkP=0000/0/0
    0:0000:002 - SN:13796-0 0 1 1 0 0 Addr=00000000:fb000000 Id=00000002
    0:0000:002 - HW: Feat=00000208 FPGA=01 XDI=01 SW=00000000
    0:0000:003 - vidi: allocated 144:72 buffers, length=4096
    0:0000:003 - vidi tx: allocated 72: buffers, length=4096
    0:0000:003 - req_dma_magic = 0x00000000.1ba20000
    0:0000:003 - ind_dma_magic = 0x00000000.07a35000
    0:0000:003 - dma_seg_len   = 32
    0:0000:003 - req_buf_len   = 4096
    0:0000:003 - ind_buf_len   = 4064
    0:0000:003 - rem_ind_cnt   = 0x00000fe0
    0:0000:004 - Initialize Softmodem!!
    0:0000:004 - task 0: sdp module not present! (own_gp=0x0, sdp_gp=0x0)
    0:0000:004 - task 1: sdp module not present! (own_gp=0x0, sdp_gp=0x0)
    0:0000:004 - ddal_load_time_init: sdp module 0 not present!
    0:0000:004 - ddal_load_time_init: sdp module 1 not present!
    0:0000:008 - init_bulk_buffers 4 65536 28672 2
    0:0000:071 - Set_LineClock_OpMode: Set to 0x0000
    0:0000:071 - [0] Starting kernel...
    0:0000:073 - [0] DSP OK
    0:0000:073 - [1] Starting kernel...
    0:0000:075 - [1] DSP OK
    0:0000:075 - Initialize IPACX in TE mode
    0:0000:075 - Hardware Initialisation done.
    0:0000:080 - PSI: init
    0:0000:080 - PSI:set etsi interface
    0:0000:080 - CREATEID ok: context:0 assigned Id:1 freeIds=ef
    0:0000:080 - manufacturer features: 0xaf307f94
    0:0000:080 - D2Assign 0 d_id=01
    0:0000:080 - MDL: init
    0:0000:080 - MDL: init 0x805d32d8 to entry 0
    0:0000:081 - PCI DMA test: write 32 bytes system(0xa03d5684) -> pci(0x2b7a9000)
    0:0000:089 - PCI DMA test: read 32 bytes pci(0x2b7a9000) -> system(0xa03d56a4)
    0:0000:090 - PCI DMA test OK
    0:0000:090 - PCI DMA write transfer 163840 bytes in 8 mSec
    0:0000:099 - PCI DMA read transfer 163840 bytes in 8 mSec
    0:0000:442 - CREATEID ok: context:ff assigned Id:2 freeIds=ee
    0:0000:457 - reset_board_license
    0:0000:458 - reseted
    0:0000:471 - DELETEID ok: deleted Id:2 freeIds=ef
    0:0000:541 - L1_UP
    0:0000:800 - D-R(003) 02 01 7F
    0:0000:800 - D-X(003) 02 01 73

Es scheint so als gäbe es das Problem bei Rufen zwischen extern ISDN und intern (NT mit Analogtelefonen) nach innen nicht.

Kann dazu jemand was (idealerweise Hilfreiches) sagen?

Kann ich nochwas schicken?


Beste Grüße,

Niels.

 

[armincm]

Ohne das Log von Asterisk zu sehen, nehme ich mal an, es hat mit dem aktivierten VOCODER der DIva zu tun. Dieses Feature ist von Dialogic eingebaut worden und ich habe damit noch keine Tests gemacht. Bitte teste mal, ob der standard CAPI voice-path besser funktioniert. Hierzu einfach das "allow=..." in der capi.conf weglassen und nur disallow=all setzen (somit werden keine RTP/VOCODER codecs aktiviert und standard alaw wird verwendet.

Armin

 

[nielsd]

sorry,

hier in *-Log eines solchen Calls anbei.

habe allow=alaw in global wie den Ports in der capi.conf auskommentiert (disallow=all steht an jedem port). Dachte ich tu der PBX was Gutes, wenn ich ihr sage, das ich nur alaw mache Die Linksys Telefone intern laufen ebenso alle auf alaw (ich nehme an und hoffe, das damit Umkodierungsaufwand entfällt...).

Meine ersten Versuche zeigen kein neues Auftreten der Drops (allerdings kann ich auch nur einseitig testen - z.B. über echo/VM von außen, da keiner dort, wo die PBX steht, der heute abnehmen kann).

Die SIP-Software (SoftIP) von Dialogic benutze ich nicht.

Ohne weiteren Hinweis hätte ich ev.

#define CAPI_MAX_B3_BLOCK_SIZE
#define RTP_HEADER_SIZE

o.ä. in der chan_capi mal angefasst, dabei aber auch eher im Dunkeln gestochert. Ein Verdacht lag auch noch im möglicherweise nicht optimal konfigurierten BIOS (Hardware-Subsystem).

Erstaunlich aber scheint schon, das Rufe von/zu ISDN->Analog (wohl weil gebrückt?) problemlos laufen.

hier während einem Call:

[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel SIP/12-0000000a                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel CAPI/ISDN1#01/38481012-c                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] VERBOSE[11883] logger.c:        > ISDN1#01: B3count is full, dropping packet.                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel SIP/12-0000000a                                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel SIP/12-0000000a                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel CAPI/ISDN1#01/38481012-c                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] VERBOSE[11883] logger.c:        > ISDN1#01: B3count is full, dropping packet.                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel SIP/12-0000000a                                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel SIP/12-0000000a                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel CAPI/ISDN1#01/38481012-c                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] VERBOSE[11883] logger.c:        > ISDN1#01: B3count is full, dropping packet.                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel SIP/12-0000000a                                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel SIP/12-0000000a                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel CAPI/ISDN1#01/38481012-c                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] VERBOSE[11883] logger.c:        > ISDN1#01: B3count is full, dropping packet.                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel SIP/12-0000000a                                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel SIP/12-0000000a                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel CAPI/ISDN1#01/38481012-c                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] VERBOSE[11883] logger.c:        > ISDN1#01: B3count is full, dropping packet.                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel SIP/12-0000000a                                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel SIP/12-0000000a                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel CAPI/ISDN1#01/38481012-c                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] VERBOSE[11883] logger.c:        > ISDN1#01: B3count is full, dropping packet.                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel SIP/12-0000000a                                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel SIP/12-0000000a                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel CAPI/ISDN1#01/38481012-c                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] VERBOSE[11883] logger.c:        > ISDN1#01: B3count is full, dropping packet.                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel SIP/12-0000000a                                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel CAPI/ISDN1#01/38481012-c                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel SIP/12-0000000a                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] rtp.c: Difference is 2088, ms is 281                                                                                                                                                
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel SIP/12-0000000a                                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel SIP/12-0000000a                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel CAPI/ISDN1#01/38481012-c                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel SIP/12-0000000a                                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel SIP/12-0000000a                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel CAPI/ISDN1#01/38481012-c                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] VERBOSE[11883] logger.c:        > ISDN1#01: B3count is full, dropping packet.                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel SIP/12-0000000a                                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel CAPI/ISDN1#01/38481012-c                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel SIP/12-0000000a                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel SIP/12-0000000a                                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel CAPI/ISDN1#01/38481012-c                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel SIP/12-0000000a                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel SIP/12-0000000a                                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel CAPI/ISDN1#01/38481012-c                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel SIP/12-0000000a                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel SIP/12-0000000a                                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel CAPI/ISDN1#01/38481012-c                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel SIP/12-0000000a                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel SIP/12-0000000a                                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                                              
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel SIP/12-0000000a                                                                                                                           
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was unlocked                                                                                                                            
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Locking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                    
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel CAPI/ISDN1#01/38481012-c                                                                                                             
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was locked                                                                                                                     
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#01/38481012-c                                                                                                                  
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel CAPI/ISDN1#01/38481012-c was unlocked                                                                                                                   
[Oct 22 14:11:39] DEBUG[11883] channel.c: ====:::: Trying to lock AST channel SIP/12-0000000a                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: :::=== Now have 1 locks (recursive)                                                                                                                                      
[Oct 22 14:11:39] DEBUG[11883] channel.c: ::::==== Channel SIP/12-0000000a was locked                                                                                                        
...
         [Oct 22 14:00:08] DEBUG[11344] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Oct 22 14:00:08] DEBUG[11344] acl.c: Found IP address for this socket
[Oct 22 14:00:08] DEBUG[11344] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.127.1:5060
[Oct 22 14:00:08] DEBUG[11344] chan_sip.c: Initializing initreq for method OPTIONS - callid [email protected]
[Oct 22 14:00:08] DEBUG[11344] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.127.243:5060
[Oct 22 14:00:08] DEBUG[11555] channel.c: ====:::: Trying to lock AST channel CAPI/ISDN1#02/01714759607-7
[Oct 22 14:00:08] DEBUG[11555] channel.c: :::=== Now have 1 locks (recursive)
[Oct 22 14:00:08] DEBUG[11555] channel.c: ::::==== Channel CAPI/ISDN1#02/01714759607-7 was locked
[Oct 22 14:00:08] DEBUG[11555] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#02/01714759607-7


....



          [Oct 22 14:00:10] DEBUG[11344] chan_sip.c: = Found Their Call ID: [email protected] Their Tag  Our tag: as782f1e44
[Oct 22 14:00:10] DEBUG[11344] chan_sip.c: Stopping retransmission on '[email protected]' of Request 102: Match Found
[Oct 22 14:00:10] NOTICE[11344] chan_sip.c: Peer '58' is now Lagged. (2257ms / 2000ms)
[Oct 22 14:00:10] DEBUG[11344] devicestate.c: Notification of state change to be queued on device/channel SIP/58
[Oct 22 14:00:10] DEBUG[11344] chan_sip.c: Destroying SIP dialog [email protected]
[Oct 22 14:00:10] DEBUG[11336] devicestate.c: No provider found, checking channel drivers for SIP - 58
[Oct 22 14:00:10] DEBUG[11336] chan_sip.c: Checking device state for peer 58
[Oct 22 14:00:10] DEBUG[11336] devicestate.c: Changing state for SIP/58 - state 5 (Unavailable)
[Oct 22 14:00:10] DEBUG[11337] devicestate.c: No provider found, checking channel drivers for SIP - 58
[Oct 22 14:00:10] DEBUG[11337] chan_sip.c: Checking device state for peer 58
[Oct 22 14:00:10] DEBUG[11337] devicestate.c: Checking if I can find provider for "Custom" - number: DND58
[Oct 22 14:00:10] DEBUG[11337] devicestate.c: Checking provider Custom with Custom
[Oct 22 14:00:10] DEBUG[11337] db.c: Unable to find key 'DND58' in family 'CustomDevstate'
[Oct 22 14:00:10] DEBUG[11337] pbx.c: FONALITY: This thread has already held the conlock, skip locking
[Oct 22 14:00:10] DEBUG[11345] app_queue.c: Device 'SIP/58' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Oct 22 14:00:10] DEBUG[11555] channel.c: ====:::: Trying to lock AST channel CAPI/ISDN1#02/01714759607-7
[Oct 22 14:00:10] DEBUG[11555] channel.c: :::=== Now have 1 locks (recursive)
[Oct 22 14:00:10] DEBUG[11555] channel.c: ::::==== Channel CAPI/ISDN1#02/01714759607-7 was locked
[Oct 22 14:00:10] DEBUG[11555] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#02/01714759607-7
[Oct 22 14:00:10] DEBUG[11555] channel.c: ::::==== Channel CAPI/ISDN1#02/01714759607-7 was unlocked
[Oct 22 14:00:10] DEBUG[11555] channel.c: ====:::: Trying to lock AST channel SIP/20-00000004


...


   [Oct 22 14:00:11] DEBUG[11555] channel.c: ::::==== Channel CAPI/ISDN1#02/01714759607-7 was unlocked
[Oct 22 14:00:11] VERBOSE[11339] logger.c: CAPI: ApplId=0x0002 Command=0x08 SubCommand=0x82 MsgNum=0x1bb9 NCCI=0x00000e01
[Oct 22 14:00:11] VERBOSE[11339] logger.c: INFO_IND                   ID=002 #0x1bb9 LEN=0039
[Oct 22 14:00:11] VERBOSE[11339] logger.c: INFO_RESP                  ID=002 #0x1bb9 LEN=0012
[Oct 22 14:00:11] VERBOSE[11339] logger.c:     -- ISDN1#02: info element FACILITY
[Oct 22 14:00:11] VERBOSE[11339] logger.c: CAPI: ApplId=0x0002 Command=0x08 SubCommand=0x82 MsgNum=0x1bba NCCI=0x00000e01
[Oct 22 14:00:11] VERBOSE[11339] logger.c: INFO_IND                   ID=002 #0x1bba LEN=0019
[Oct 22 14:00:11] VERBOSE[11339] logger.c: INFO_RESP                  ID=002 #0x1bba LEN=0012
[Oct 22 14:00:11] VERBOSE[11339] logger.c:     -- ISDN1#02: info element CHARGE in UNITS
[Oct 22 14:00:11] VERBOSE[11339] logger.c: CAPI: ApplId=0x0002 Command=0x08 SubCommand=0x82 MsgNum=0x1bbb NCCI=0x00000e01
[Oct 22 14:00:11] VERBOSE[11339] logger.c: INFO_IND                   ID=002 #0x1bbb LEN=0015
[Oct 22 14:00:11] VERBOSE[11339] logger.c: INFO_RESP                  ID=002 #0x1bbb LEN=0012
[Oct 22 14:00:11] VERBOSE[11339] logger.c:     -- ISDN1#02: info element FACILITY
[Oct 22 14:00:11] DEBUG[11555] channel.c: ====:::: Trying to lock AST channel CAPI/ISDN1#02/01714759607-7
[Oct 22 14:00:11] DEBUG[11555] channel.c: :::=== Now have 1 locks (recursive)
[Oct 22 14:00:11] DEBUG[11555] channel.c: ::::==== Channel CAPI/ISDN1#02/01714759607-7 was locked
[Oct 22 14:00:11] DEBUG[11555] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#02/01714759607-7
[Oct 22 14:00:11] DEBUG[11555] channel.c: ::::==== Channel CAPI/ISDN1#02/01714759607-7 was unlocked

...

[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Unlocking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was unlocked
[Oct 22 14:00:12] DEBUG[11555] pbx.c: Launching 'Macro'
[Oct 22 14:00:12] VERBOSE[11555] logger.c:     -- Executing [h@macro-dialout-trunk:1] Macro("SIP/20-00000004", "hangupcall,") in new stack
[Oct 22 14:00:12] DEBUG[11555] channel.c: ====:::: Locking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: :::=== Now have 1 locks (recursive)
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was locked
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Unlocking AST channel SIP/20-00000004


...

[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was unlocked
[Oct 22 14:00:12] DEBUG[11555] pbx.c: Expression result is '1'
[Oct 22 14:00:12] DEBUG[11555] pbx.c: Launching 'GotoIf'
[Oct 22 14:00:12] VERBOSE[11555] logger.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/20-00000004", "1?skiprg") in new stack
[Oct 22 14:00:12] DEBUG[11555] channel.c: ====:::: Locking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: :::=== Now have 1 locks (recursive)
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was locked
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Unlocking AST channel SIP/20-00000004


...

[Oct 22 14:00:12] DEBUG[11555] pbx.c: Expression result is '1'
[Oct 22 14:00:12] DEBUG[11555] pbx.c: Launching 'GotoIf'
[Oct 22 14:00:12] VERBOSE[11555] logger.c:     -- Executing [s@macro-hangupcall:4] GotoIf("SIP/20-00000004", "1?skipblkvm") in new stack
[Oct 22 14:00:12] DEBUG[11555] channel.c: ====:::: Locking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: :::=== Now have 1 locks (recursive)

...

[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was unlocked
[Oct 22 14:00:12] DEBUG[11555] pbx.c: Launching 'Hangup'
[Oct 22 14:00:12] VERBOSE[11555] logger.c:     -- Executing [s@macro-hangupcall:9] Hangup("SIP/20-00000004", "") in new stack
[Oct 22 14:00:12] DEBUG[11555] app_macro.c: Spawn extension (macro-hangupcall,s,9) exited non-zero on 'SIP/20-00000004' in macro 'hangupcall'
[Oct 22 14:00:12] VERBOSE[11555] logger.c:   == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/20-00000004' in macro 'hangupcall'
[Oct 22 14:00:12] DEBUG[11555] channel.c: ====:::: Locking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: :::=== Now have 1 locks (recursive)


...

[Oct 22 14:00:12] DEBUG[11555] channel.c: :::=== Still have 1 locks (recursive)
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was unlocked
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Unlocking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was unlocked
[Oct 22 14:00:12] DEBUG[11555] features.c: Spawn extension (macro-dialout-trunk,h,1) exited non-zero on 'SIP/20-00000004'
[Oct 22 14:00:12] VERBOSE[11555] logger.c:   == Spawn extension (macro-dialout-trunk, h, 1) exited non-zero on 'SIP/20-00000004'
[Oct 22 14:00:12] DEBUG[11555] channel.c: ====:::: Locking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: :::=== Now have 1 locks (recursive)
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was locked
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Unlocking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was unlocked
[Oct 22 14:00:12] VERBOSE[11339] logger.c: CAPI: ApplId=0x0002 Command=0x84 SubCommand=0x82 MsgNum=0x1bf2 NCCI=0x00030e01
[Oct 22 14:00:12] VERBOSE[11339] logger.c: DISCONNECT_B3_IND          ID=002 #0x1bf2 LEN=0015
[Oct 22 14:00:12] VERBOSE[11339] logger.c: DISCONNECT_B3_RESP         ID=002 #0x1bf2 LEN=0012
[Oct 22 14:00:12] DEBUG[11555] cdr_addon_mysql.c: Inserting a CDR record.
[Oct 22 14:00:12] DEBUG[11555] cdr_addon_mysql.c: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,uniqueid) VALU$
[Oct 22 14:00:12] DEBUG[11555] channel.c: ====:::: Locking AST channel CAPI/ISDN1#02/01714759607-7
[Oct 22 14:00:12] DEBUG[11555] channel.c: :::=== Now have 1 locks (recursive)
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel CAPI/ISDN1#02/01714759607-7 was locked
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#02/01714759607-7
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel CAPI/ISDN1#02/01714759607-7 was unlocked
[Oct 22 14:00:12] DEBUG[11555] channel.c: ====:::: Locking AST channel CAPI/ISDN1#02/01714759607-7
[Oct 22 14:00:12] DEBUG[11555] channel.c: :::=== Now have 1 locks (recursive)
...
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Unlocking AST channel CAPI/ISDN1#02/01714759607-7
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel CAPI/ISDN1#02/01714759607-7 was unlocked
[Oct 22 14:00:12] DEBUG[11555] devicestate.c: Notification of state change to be queued on device/channel CAPI/ISDN1#02/01714759607

...

[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was unlocked
[Oct 22 14:00:12] DEBUG[11555] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Oct 22 14:00:12] DEBUG[11555] app_macro.c: Spawn extension (macro-dialout-trunk,s,26) exited non-zero on 'SIP/20-00000004' in macro 'dialout-trunk'
[Oct 22 14:00:12] VERBOSE[11555] logger.c:   == Spawn extension (macro-dialout-trunk, s, 26) exited non-zero on 'SIP/20-00000004' in macro 'dialout-trunk'
[Oct 22 14:00:12] DEBUG[11555] channel.c: ====:::: Locking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: :::=== Now have 1 locks (recursive)
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was locked

...

[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was unlocked
[Oct 22 14:00:12] DEBUG[11555] pbx.c: Spawn extension (from-internal,h,1) exited non-zero on 'SIP/20-00000004'
[Oct 22 14:00:12] VERBOSE[11555] logger.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/20-00000004'
[Oct 22 14:00:12] DEBUG[11555] channel.c: ====:::: Locking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: :::=== Now have 1 locks (recursive)
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was locked
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Unlocking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was unlocked
[Oct 22 14:00:12] DEBUG[11555] channel.c: ====:::: Locking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: :::=== Now have 1 locks (recursive)
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was locked
[Oct 22 14:00:12] DEBUG[11555] channel.c: Hanging up channel 'SIP/20-00000004'
[Oct 22 14:00:12] DEBUG[11555] chan_sip.c: Hangup call SIP/20-00000004, SIP callid [email protected]
[Oct 22 14:00:12] DEBUG[11555] chan_sip.c: Updating call counter for incoming call
[Oct 22 14:00:12] DEBUG[11555] devicestate.c: Notification of state change to be queued on device/channel SIP/20
[Oct 22 14:00:12] DEBUG[11555] chan_sip.c: Trying to put 'BYE sip:20@' onto UDP socket destined for 192.168.127.254:5060
[Oct 22 14:00:12] DEBUG[11555] channel.c: ====:::: Locking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: :::=== Now have 2 locks (recursive)
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was locked
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Unlocking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: :::=== Still have 1 locks (recursive)
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was unlocked
[Oct 22 14:00:12] DEBUG[11555] channel.c: ====:::: Locking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: :::=== Now have 2 locks (recursive)
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was locked
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Unlocking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: :::=== Still have 1 locks (recursive)
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was unlocked
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Unlocking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was unlocked
[Oct 22 14:00:12] DEBUG[11555] channel.c: ====:::: Locking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: :::=== Now have 1 locks (recursive)
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was locked
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Unlocking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was unlocked
[Oct 22 14:00:12] DEBUG[11555] channel.c: ====:::: Locking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: :::=== Now have 1 locks (recursive)
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was locked
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Unlocking AST channel SIP/20-00000004
[Oct 22 14:00:12] DEBUG[11555] channel.c: ::::==== Channel SIP/20-00000004 was unlocked
[Oct 22 14:00:12] DEBUG[11555] devicestate.c: Notification of state change to be queued on device/channel SIP/20
[Oct 22 14:00:12] DEBUG[11336] devicestate.c: No provider found, checking channel drivers for CAPI - ISDN1#02/01714759607
[Oct 22 14:00:12] VERBOSE[11336] logger.c:        > chan_capi devicestate requested for ISDN1#02/01714759607 is 'Not in use'
[Oct 22 14:00:12] DEBUG[11336] devicestate.c: Changing state for CAPI/ISDN1#02/01714759607 - state 1 (Not in use)

Möglicherweise aber war/ist mein Debugging ins full Log wie auf der Console einfach zu "I/O-strapaziös"?

Hier wohl dazugehörige Rufaufbauten (habe das Debug-Log etwas gerafft, da sonst wirklich (!) sehr lang. Insbesondere die laufend wiederholdenden locking/unlocking Einträge habe ich weitgehend herausgefiltert, da immer gleichlautend.):

[Oct 22 13:55:53] VERBOSE[11451] logger.c:   == ISDN1#02: Requested RINGING-Indication for CAPI/ISDN1#02/38481030-4                                                                                                
[Oct 22 13:55:53] VERBOSE[11451] logger.c:     -- ISDN1#02: attempting ALERT in state 1                                                                                                                            
[Oct 22 13:55:53] DEBUG[11451] channel.c: Driver for channel 'CAPI/ISDN1#02/38481030-4' does not support indication 3, emulating it                                                                                
[Oct 22 13:55:53] DEBUG[11451] channel.c: Prodding channel 'CAPI/ISDN1#02/38481030-4'                                                                                                                              
[Oct 22 13:55:53] DEBUG[11451] channel.c: Set channel CAPI/ISDN1#02/38481030-4 to write format slin                                                                                                                
[Oct 22 13:55:53] DEBUG[11336] devicestate.c: No provider found, checking channel drivers for SIP - 30                                                                                                             
[Oct 22 13:55:53] DEBUG[11336] chan_sip.c: Checking device state for peer 30                                                                                                                                       
[Oct 22 13:55:53] DEBUG[11336] devicestate.c: Changing state for SIP/30 - state 6 (Ringing)                                                                                                                        
[Oct 22 13:55:53] DEBUG[11337] devicestate.c: No provider found, checking channel drivers for SIP - 30                                                                                                             
[Oct 22 13:55:53] DEBUG[11337] chan_sip.c: Checking device state for peer 30                                                                                                                                       
[Oct 22 13:55:53] DEBUG[11337] devicestate.c: Checking if I can find provider for "Custom" - number: DND30                                                                                                         
[Oct 22 13:55:53] DEBUG[11337] devicestate.c: Checking provider Custom with Custom                                                                                                                                 
[Oct 22 13:55:53] DEBUG[11337] db.c: Unable to find key 'DND30' in family 'CustomDevstate'                                                                                                                         
[Oct 22 13:55:53] DEBUG[11345] app_queue.c: Device 'SIP/30' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.                                                            
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)                                                                                                           
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.127.1:5060                                                                                                               
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Initializing initreq for method OPTIONS - callid [email protected]                                                              
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: = Found Their Call ID: [email protected] Their Tag  Our tag: as5a291b78                                                         
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Stopping retransmission on '[email protected]' of Request 102: Match Found                                                      
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Destroying SIP dialog [email protected]                                                                                         
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)                                                                                                           
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.127.1:5060                                                                                                               
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Initializing initreq for method OPTIONS - callid [email protected]                                                              
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: = Found Their Call ID: [email protected] Their Tag  Our tag: as1af75aa2                                                         
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Stopping retransmission on '[email protected]' of Request 102: Match Found                                                      
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Destroying SIP dialog [email protected]                                                                                         
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)                                                                                                           
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.127.1:5060                                                                                                               
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Initializing initreq for method OPTIONS - callid [email protected]                                                              
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: = Found Their Call ID: [email protected] Their Tag  Our tag: as7ca38637                                                         
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Stopping retransmission on '[email protected]' of Request 102: Match Found                                                      
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Destroying SIP dialog [email protected]                                                                                         
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)                                                                                                           
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.127.1:5060                                                                                                               
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Initializing initreq for method OPTIONS - callid [email protected]                                                              
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: = Found Their Call ID: [email protected] Their Tag  Our tag: as745d773f                                                         
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Stopping retransmission on '[email protected]' of Request 102: Match Found                                                      
[Oct 22 13:55:54] DEBUG[11344] chan_sip.c: Destroying SIP dialog [email protected]                                                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)                                                                                                           
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.127.1:5060                                                                                                               
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Initializing initreq for method OPTIONS - callid [email protected]                                                              
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: = Found Their Call ID: [email protected] Their Tag  Our tag: as2bf7d7bd                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Stopping retransmission on '[email protected]' of Request 102: Match Found                                                      
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Destroying SIP dialog [email protected]                                                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)                                                                                                           
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.127.1:5060                                                                                                               
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Initializing initreq for method OPTIONS - callid [email protected]                                                              
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: = Found Their Call ID: [email protected] Their Tag  Our tag: as43d37988                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Stopping retransmission on '[email protected]' of Request 102: Match Found                                                      
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Destroying SIP dialog [email protected]                                                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)                                                                                                           
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.127.1:5060                                                                                                               
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Initializing initreq for method OPTIONS - callid [email protected]                                                              
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: = Found Their Call ID: [email protected] Their Tag  Our tag: as1ecef309                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Stopping retransmission on '[email protected]' of Request 102: Match Found                                                      
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Destroying SIP dialog [email protected]                                                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)                                                                                                           
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.127.1:5060                                                                                                               
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Initializing initreq for method OPTIONS - callid [email protected]                                                              
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)                                                                                                           
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.127.1:5060                                                                                                               
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Initializing initreq for method OPTIONS - callid [email protected]                                                              
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)                                                                                                           
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.127.1:5060                                                                                                               
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Initializing initreq for method OPTIONS - callid [email protected]                                                              
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: = No match Their Call ID: [email protected] Their Tag  Our tag: as06357281                                                      
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: = No match Their Call ID: [email protected] Their Tag  Our tag: as28fc9f27                                                      
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: = Found Their Call ID: [email protected] Their Tag  Our tag: as6555a1dc                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Stopping retransmission on '[email protected]' of Request 102: Match Found                                                      
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Destroying SIP dialog [email protected]                                                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: = No match Their Call ID: [email protected] Their Tag  Our tag: as06357281                                                      
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: = Found Their Call ID: [email protected] Their Tag  Our tag: as28fc9f27                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Stopping retransmission on '[email protected]' of Request 102: Match Found                                                      
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Destroying SIP dialog [email protected]                                                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: = Found Their Call ID: [email protected] Their Tag  Our tag: as06357281                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Stopping retransmission on '[email protected]' of Request 102: Match Found                                                      
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Destroying SIP dialog [email protected]                                                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)                                                                                                           
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.127.1:5060                                                                                                               
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Initializing initreq for method OPTIONS - callid [email protected]                                                              
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: = Found Their Call ID: [email protected] Their Tag  Our tag: as25f771ad                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Stopping retransmission on '[email protected]' of Request 102: Match Found                                                      
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Destroying SIP dialog [email protected]                                                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)                                                                                                           
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.127.1:5060                                                                                                               
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Initializing initreq for method OPTIONS - callid [email protected]                                                              
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: = Found Their Call ID: [email protected] Their Tag  Our tag: as3e426235                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Stopping retransmission on '[email protected]' of Request 102: Match Found                                                      
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Destroying SIP dialog [email protected]                                                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)                                                                                                           
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.127.1:5060                                                                                                               
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Initializing initreq for method OPTIONS - callid [email protected]                                                              
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: = Found Their Call ID: [email protected] Their Tag  Our tag: as4c2742a2                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Stopping retransmission on '[email protected]' of Request 102: Match Found                                                      
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Destroying SIP dialog [email protected]                                                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)                                                                                                           
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.127.1:5060                                                                                                               
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Initializing initreq for method OPTIONS - callid [email protected]                                                              
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: = Found Their Call ID: [email protected] Their Tag  Our tag: as66023b79                                                         
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Stopping retransmission on '[email protected]' of Request 102: Match Found                                                      
[Oct 22 13:55:55] DEBUG[11344] chan_sip.c: Destroying SIP dialog [email protected]                                                                                         
[Oct 22 13:55:59] DEBUG[11344] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)                                                                                                           
[Oct 22 13:55:59] DEBUG[11344] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.127.1:5060                                                                                                               
[Oct 22 13:55:59] DEBUG[11344] chan_sip.c: Initializing initreq for method OPTIONS - callid [email protected]

Hilft das? Oder kann ich nochwas beisteuern.

btw:
hat jemand noch Tips zur optimalen Konfiguration der Linksys / Cisco SPA 922 phones an Asterisk / ISDN (abweichend zur Default Konfig - z.B. Echocancel, Komfortrauschen, Codecs usw.)?


Beste Grüße,


Niels.