[asterisk-users] transfer=mediaonly : can't hear nothing

Simone Cittadini mymailforlists at gmail.com
Tue Mar 20 03:36:17 MST 2007


Kevin P. Fleming ha scritto:
>
> OK, then you'll need to get a verbose/debug console trace, and
> preferably a packet capture of the IAX2 traffic on 'Server', and post a
> bug on bugs.digium.com with those files attached.
> _______________________________________________
While setting up the servers to gather the logs I've tryed a 
configuration which is so "hello world" it seems unprobable to me it 
can't work due to a bug.

I post once again here, sorry for the verbosity, if then in your opinion 
there's still something wrong with * internals and not with my 
understanding of the configs I'll open the bug.
I anticipate that only with mediaonly (when I can't hear) I get these 
messages : "Received iseqno 4 not within window 5->5" which seems to 
remand to bug number 0006808, but I've tested also with jitterbuffer=no 
on all machines and the problem remains.
Also I get some "Subclass: (38?)" packets, only in mediaonly mode.

3 machines, all on the same class C net (192.168.52.x), 2 are "clients" 
(C001 and C002) and one is the "server"

C001 has two nics, the second being 192.168.0.1 connected to a switch 
with a linksys pap in it, which generates the call:

C001 and C002 sip.conf, iax.conf and extensions.conf are the same 
(except of course for IPs where to listen and credentials)

C00x sip.conf:

[general]
context=default                 ; Default context for incoming calls
realm=retireti.it
bindport=5060                   ; UDP Port to bind to (SIP standard port 
is 5060)
bindaddr=192.168.0.1                ; IP address to bind to (0.0.0.0 
binds to all)
srvlookup=no
tos_sip=cs3                    ; Sets TOS for SIP packets.
tos_audio=ef                   ; Sets TOS for RTP audio packets.
disallow=all
allow = alaw
language=it
dtmfmode = inband
progressinband=no
canreinvite=no
qualify=yes

jbenable = no
jbforce = no
jbmaxsize = 400
jbimpl = adaptive

[0100x01]
type=friend
secret=0100x00
context=outgoing
callerid=("whatever" <0100x01>)
host=dynamic


C00x iax.conf:

[general]
bindport=4569
bindaddr=192.168.52.9x (C001 .94 and C002 .95)
language=it
disallow=all
allow = alaw
allow = gsm
jitterbuffer = yes
forcejitterbuffer = no
maxjitterbuffer = 400
dropcount=2
maxjitterinterps=10
resyncthreshold=1000
maxexcessbuffer=80
minexcessbuffer=10
jittershrinkrate=1

autokill=yes
auth=md5

register => 0100x01:0100x00 at 192.168.52.56

[server]
type=friend
context=incoming
secret=pwd
auth=md5
host=192.168.52.56
disallow=all
allow=alaw
allow=gsm


C00x extensions.conf :

[general]
static = yes
writeprotect = no
clearglobalvars = no

[globals]
CODACCOUNT = 0100x01
PWD = 0100x00
SERVER = 192.168.52.56

[outgoing]
exten => _X.,1,NoOp(esco)
;exten => _X.,n,Dial(IAX2/${CODACCOUNT}:${PWD}@${SERVER}/${EXTEN})
exten => _X.,n,Dial(IAX2/${CODACCOUNT}:${PWD}@server/${EXTEN})
exten => _X.,n,Hangup

[incoming]
exten => _X.,1,NoOp(entro)
exten => _X.,n,Answer
exten => _X.,n,Playback(tt-weasels)
exten => _X.,n,Echo
exten => _X.,n,Hangup


now Server configs :

iax.conf :

[general]
bindport=4569
bindaddr=192.168.52.56
language=it
disallow=all
allow=alaw
allow=gsm
jitterbuffer = yes
forcejitterbuffer = no
maxjitterbuffer = 100
dropcount=2
maxjitterinterps=10
resyncthreshold=1000
maxexcessbuffer=80
minexcessbuffer=10
jittershrinkrate=1
context=default
autokill=yes

[0100101]
username=0100101
type=friend
secret=0100100
auth=md5
host=dynamic
context=default
callerid=0100101
transfer=no
qualify=yes

[0100201]
username=0100201
type=friend
secret=0100200
auth=md5
host=dynamic
context=default
callerid=0100201
transfer=no
qualify=yes


extensions.conf

[general]
static=yes
writeprotect=no
clearglobalvars=no

[globals]

[default]

exten => _X.,1,NoOp(here we are)
exten => _X.,n,Dial(IAX2/server:pwd at 0100201/${EXTEN})
exten => _X.,n,Hangup

As you can see I've removed the realtime engine, and I've no "input 
client" and "termination clients" difference, C001 calls the server, 
which calls C002, which playback something and then Echoes, anyway both 
C001 and C002 are the same type of "registered, monitored friends" for 
the Server.

transfer=no, and all works ok, with debug,verbose and 'iax2 set debug' I 
see in Server's CLI :

*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     
Subclass: NEW
   Timestamp: 00010ms  SCall: 00006  DCall: 00000 [192.168.52.94:4569]
   VERSION         : 2
   CALLED NUMBER   : 12
   CODEC_PREFS     : (alaw|gsm)
   CALLING NUMBER  : 0100101
   CALLING PRESNTN : 0
   CALLING TYPEOFN : 0
   CALLING TRANSIT : 0
   CALLING NAME    : whatever
   LANGUAGE        : it
   USERNAME        : 0100101
   FORMAT          : 8
   CAPABILITY      : 57354
   ADSICPE         : 2
   DATE TIME       : 2007-03-20  12:16:30

Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: 
AUTHREQ
   Timestamp: 00013ms  SCall: 00003  DCall: 00006 [192.168.52.94:4569]
   AUTHMETHODS     : 2
   CHALLENGE       : 347981677
   USERNAME        : 0100101

Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: 
AUTHREP
   Timestamp: 00030ms  SCall: 00006  DCall: 00003 [192.168.52.94:4569]
   MD5 RESULT      : 32e6d2ead1582051eee0d54060bd00de

    -- Accepting AUTHENTICATED call from 192.168.52.94:
       > requested format = alaw,
       > requested prefs = (alaw|gsm),
       > actual format = alaw,
       > host prefs = (alaw|gsm),
       > priority = mine
Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: 
ACCEPT
   Timestamp: 00014ms  SCall: 00003  DCall: 00006 [192.168.52.94:4569]
   FORMAT          : 8

    -- Executing [12 at default:1] NoOp("IAX2/0100101-3", "here we are") in 
new stack
    -- Executing [12 at default:2] Dial("IAX2/0100101-3", 
"IAX2/server:pwd at 0100201/12") in new stack
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK
   Timestamp: 00014ms  SCall: 00006  DCall: 00003 [192.168.52.94:4569]
    -- Called server:pwd at 0100201/12
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: NEW
   Timestamp: 00017ms  SCall: 00004  DCall: 00000 [192.168.52.95:4569]
   VERSION         : 2
   CALLED NUMBER   : 12
   CODEC_PREFS     : (alaw|gsm)
   CALLING NUMBER  : 0100101
   CALLING PRESNTN : 1
   CALLING TYPEOFN : 0
   CALLING TRANSIT : 0
   CALLING NAME    :
   LANGUAGE        : it
   USERNAME        : server
   FORMAT          : 8
   CAPABILITY      : 57354
   ADSICPE         : 2
   DATE TIME       : 2007-03-20  11:12:24

Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: 
AUTHREQ
   Timestamp: 00015ms  SCall: 00006  DCall: 00004 [192.168.52.95:4569]
   AUTHMETHODS     : 2
   CHALLENGE       : 167609855
   USERNAME        : server

Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: 
AUTHREP
   Timestamp: 00022ms  SCall: 00004  DCall: 00006 [192.168.52.95:4569]
   MD5 RESULT      : 9a8b1911a409f8823563157ffea9f8d2

Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: 
ACCEPT
   Timestamp: 00017ms  SCall: 00006  DCall: 00004 [192.168.52.95:4569]
   FORMAT          : 8

    -- Call accepted by 192.168.52.95 (format alaw)
    -- Format for call is alaw
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK
   Timestamp: 00017ms  SCall: 00004  DCall: 00006 [192.168.52.95:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: 
ANSWER
   Timestamp: 00020ms  SCall: 00006  DCall: 00004 [192.168.52.95:4569]
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK
   Timestamp: 00020ms  SCall: 00004  DCall: 00006 [192.168.52.95:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 002 Type: VOICE   Subclass: 8
   Timestamp: 00040ms  SCall: 00006  DCall: 00004 [192.168.52.95:4569]
[Mar 20 11:12:25] DEBUG[8019]: chan_iax2.c:6649 socket_process: Ooh, 
voice format changed to 8
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 004 Type: IAX     Subclass: ACK
   Timestamp: 00040ms  SCall: 00004  DCall: 00006 [192.168.52.95:4569]
    -- IAX2/0100201-4 answered IAX2/0100101-3
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: 
ANSWER
   Timestamp: 00017ms  SCall: 00003  DCall: 00006 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK
   Timestamp: 00017ms  SCall: 00006  DCall: 00003 [192.168.52.94:4569]
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 002 Type: VOICE   Subclass: 8
   Timestamp: 00055ms  SCall: 00003  DCall: 00006 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 003 Type: IAX     Subclass: VNAK
   Timestamp: 00108ms  SCall: 00006  DCall: 00003 [192.168.52.94:4569]
[Mar 20 11:12:25] DEBUG[8025]: chan_iax2.c:7333 socket_process: Received 
VNAK: resending outstanding frames
Tx-Frame Retry[001] -- OSeqno: 003 ISeqno: 002 Type: VOICE   Subclass: 8
   Timestamp: 00055ms  SCall: 00003  DCall: 00006 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 003 Type: IAX     Subclass: VNAK
   Timestamp: 00111ms  SCall: 00006  DCall: 00003 [192.168.52.94:4569]
[Mar 20 11:12:25] DEBUG[8026]: chan_iax2.c:7333 socket_process: Received 
VNAK: resending outstanding frames
Tx-Frame Retry[001] -- OSeqno: 003 ISeqno: 002 Type: VOICE   Subclass: 8
   Timestamp: 00055ms  SCall: 00003  DCall: 00006 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 003 Type: IAX     Subclass: VNAK
   Timestamp: 00114ms  SCall: 00006  DCall: 00003 [192.168.52.94:4569]
[Mar 20 11:12:25] DEBUG[8027]: chan_iax2.c:7333 socket_process: Received 
VNAK: resending outstanding frames
Tx-Frame Retry[001] -- OSeqno: 003 ISeqno: 002 Type: VOICE   Subclass: 8
   Timestamp: 00055ms  SCall: 00003  DCall: 00006 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 004 Type: IAX     Subclass: ACK
   Timestamp: 00055ms  SCall: 00006  DCall: 00003 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 004 Type: IAX     Subclass: ACK
   Timestamp: 00055ms  SCall: 00006  DCall: 00003 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 004 Type: IAX     Subclass: ACK
   Timestamp: 00055ms  SCall: 00006  DCall: 00003 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 004 Type: IAX     Subclass: ACK
   Timestamp: 00055ms  SCall: 00006  DCall: 00003 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 004 Type: VOICE   Subclass: 8
   Timestamp: 00175ms  SCall: 00006  DCall: 00003 [192.168.52.94:4569]
[Mar 20 11:12:25] DEBUG[8026]: chan_iax2.c:6649 socket_process: Ooh, 
voice format changed to 8
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 003 Type: IAX     Subclass: ACK
   Timestamp: 00175ms  SCall: 00003  DCall: 00006 [192.168.52.94:4569]
[Mar 20 11:12:25] DEBUG[8043]: chan_iax2.c:3454 calc_timestamp: 
predicted timestamp skew (175) > max (160), using real ts instead.
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 004 Type: VOICE   Subclass: 8
   Timestamp: 00180ms  SCall: 00004  DCall: 00006 [192.168.52.95:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 003 Type: IAX     Subclass: ACK
   Timestamp: 00180ms  SCall: 00006  DCall: 00004 [192.168.52.95:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 004 Type: IAX     Subclass: 
HANGUP
   Timestamp: 08576ms  SCall: 00006  DCall: 00003 [192.168.52.94:4569]
   CAUSE CODE      : 16

[Mar 20 11:12:33] DEBUG[8018]: chan_iax2.c:6944 socket_process: 
Immediately destroying 3, having received hangup
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 004 Type: IAX     Subclass: ACK
   Timestamp: 08576ms  SCall: 00003  DCall: 00006 [192.168.52.94:4569]
[Mar 20 11:12:34] DEBUG[8043]: chan_iax2.c:2937 iax2_hangup: We're 
hanging up IAX2/0100201-4 now...
    -- Hungup 'IAX2/0100201-4'
  == Spawn extension (default, 12, 2) exited non-zero on 'IAX2/0100101-3'
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 004 Type: IAX     Subclass: 
HANGUP
   Timestamp: 08602ms  SCall: 00004  DCall: 00006 [192.168.52.95:4569]
   CAUSE CODE      : 16

Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: IAX     Subclass: ACK
   Timestamp: 08602ms  SCall: 00006  DCall: 00004 [192.168.52.95:4569]
[Mar 20 11:12:34] DEBUG[8043]: cdr_addon_mysql.c:210 mysql_log: 
cdr_mysql: inserting a CDR record.
[Mar 20 11:12:34] DEBUG[8043]: cdr_addon_mysql.c:226 mysql_log: 
cdr_mysql: SQL command as follows: INSERT INTO cdr 
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield) 
VALUES ('2007-03-20 11:12:25','0100101','0100101','12','default', 
'IAX2/0100101-3','IAX2/0100201-4','Dial','IAX2/server:pwd at 0100201/12',9,9,'ANSWERED',3,'','')
[Mar 20 11:12:34] DEBUG[8043]: chan_iax2.c:2937 iax2_hangup: We're 
hanging up IAX2/0100101-3 now...
[Mar 20 11:12:34] DEBUG[8043]: chan_iax2.c:2947 iax2_hangup: Really 
destroying IAX2/0100101-3 now...
    -- Hungup 'IAX2/0100101-3'


##############################
Lets change transfer=mediaonly in Server's iax.conf (both entries), I 
hear only "wease.." from the playback, then nothing
I go verbose, look for : "Received iseqno 4 not within window 5->5" and 
"Tx-Frame Retry[000] -- OSeqno: 005 ISeqno: 004 Type: IAX     Subclass: 
(38?)"


*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     
Subclass: NEW
   Timestamp: 00009ms  SCall: 00005  DCall: 00000 [192.168.52.94:4569]
   VERSION         : 2
   CALLED NUMBER   : 12
   CODEC_PREFS     : (alaw|gsm)
   CALLING NUMBER  : 0100101
   CALLING PRESNTN : 0
   CALLING TYPEOFN : 0
   CALLING TRANSIT : 0
   CALLING NAME    : whatever
   LANGUAGE        : it
   USERNAME        : 0100101
   FORMAT          : 8
   CAPABILITY      : 57354
   ADSICPE         : 2
   DATE TIME       : 2007-03-20  12:19:52

Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: 
AUTHREQ
   Timestamp: 00014ms  SCall: 00003  DCall: 00005 [192.168.52.94:4569]
   AUTHMETHODS     : 2
   CHALLENGE       : 170169981
   USERNAME        : 0100101

Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: 
AUTHREP
   Timestamp: 00034ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
   MD5 RESULT      : a9065963c5fbae3d35bf39bb3e92699b

    -- Accepting AUTHENTICATED call from 192.168.52.94:
       > requested format = alaw,
       > requested prefs = (alaw|gsm),
       > actual format = alaw,
       > host prefs = (alaw|gsm),
       > priority = mine
Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: 
ACCEPT
   Timestamp: 00040ms  SCall: 00003  DCall: 00005 [192.168.52.94:4569]
   FORMAT          : 8

    -- Executing [12 at default:1] NoOp("IAX2/0100101-3", "here we are") in 
new stack
    -- Executing [12 at default:2] Dial("IAX2/0100101-3", 
"IAX2/server:pwd at 0100201/12") in new stack
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK
   Timestamp: 00040ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
    -- Called server:pwd at 0100201/12
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: NEW
   Timestamp: 00002ms  SCall: 00004  DCall: 00000 [192.168.52.95:4569]
   VERSION         : 2
   CALLED NUMBER   : 12
   CODEC_PREFS     : (alaw|gsm)
   CALLING NUMBER  : 0100101
   CALLING PRESNTN : 1
   CALLING TYPEOFN : 0
   CALLING TRANSIT : 0
   CALLING NAME    :
   LANGUAGE        : it
   USERNAME        : server
   FORMAT          : 8
   CAPABILITY      : 57354
   ADSICPE         : 2
   DATE TIME       : 2007-03-20  11:15:46

Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: 
AUTHREQ
   Timestamp: 00006ms  SCall: 00005  DCall: 00004 [192.168.52.95:4569]
   AUTHMETHODS     : 2
   CHALLENGE       : 818191730
   USERNAME        : server

Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: 
AUTHREP
   Timestamp: 00006ms  SCall: 00004  DCall: 00005 [192.168.52.95:4569]
   MD5 RESULT      : a76bfbc04b8d5b71af86cc9ccf4cb819

Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: 
ACCEPT
   Timestamp: 00007ms  SCall: 00005  DCall: 00004 [192.168.52.95:4569]
   FORMAT          : 8

    -- Call accepted by 192.168.52.95 (format alaw)
    -- Format for call is alaw
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK
   Timestamp: 00007ms  SCall: 00004  DCall: 00005 [192.168.52.95:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: 
ANSWER
   Timestamp: 00010ms  SCall: 00005  DCall: 00004 [192.168.52.95:4569]
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK
   Timestamp: 00010ms  SCall: 00004  DCall: 00005 [192.168.52.95:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 002 Type: VOICE   Subclass: 8
   Timestamp: 00020ms  SCall: 00005  DCall: 00004 [192.168.52.95:4569]
[Mar 20 11:15:47] DEBUG[8170]: chan_iax2.c:6649 socket_process: Ooh, 
voice format changed to 8
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 004 Type: IAX     Subclass: ACK
   Timestamp: 00020ms  SCall: 00004  DCall: 00005 [192.168.52.95:4569]
    -- IAX2/0100201-4 answered IAX2/0100101-3
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: 
ANSWER
   Timestamp: 00043ms  SCall: 00003  DCall: 00005 [192.168.52.94:4569]
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 002 Type: IAX     Subclass: TXREQ
   Timestamp: 00095ms  SCall: 00003  DCall: 00005 [192.168.52.94:4569]
   APPARENT ADDRES : IPV4 192.168.52.95:4569
   CALL NUMBER     : 5
   TRANSFER ID     : 133782656

Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK
   Timestamp: 00043ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 004 Type: IAX     Subclass: ACK
   Timestamp: 00095ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 004 Type: IAX     Subclass: TXREQ
   Timestamp: 00056ms  SCall: 00004  DCall: 00005 [192.168.52.95:4569]
   APPARENT ADDRES : IPV4 192.168.52.94:4569
   CALL NUMBER     : 5
   TRANSFER ID     : 133782656

Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 003 Type: IAX     Subclass: ACK
   Timestamp: 00056ms  SCall: 00005  DCall: 00004 [192.168.52.95:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 003 Type: IAX     Subclass: 
TXREADY
   Timestamp: 00066ms  SCall: 00005  DCall: 00004 [192.168.52.95:4569]
   CALL NUMBER     : 5

    -- Channel 'IAX2/0100201-4' ready to transfer
Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 005 Type: IAX     Subclass: ACK
   Timestamp: 00066ms  SCall: 00004  DCall: 00005 [192.168.52.95:4569]
Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 002 Type: VOICE   Subclass: 8
   Timestamp: 00059ms  SCall: 00003  DCall: 00005 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: IAX     Subclass: VNAK
   Timestamp: 00171ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
[Mar 20 11:15:47] DEBUG[8174]: chan_iax2.c:7333 socket_process: Received 
VNAK: resending outstanding frames
Tx-Frame Retry[001] -- OSeqno: 004 ISeqno: 002 Type: VOICE   Subclass: 8
   Timestamp: 00059ms  SCall: 00003  DCall: 00005 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 005 Type: IAX     Subclass: ACK
   Timestamp: 00059ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 005 Type: IAX     Subclass: ACK
   Timestamp: 00059ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: IAX     Subclass: VNAK
   Timestamp: 00162ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
[Mar 20 11:15:47] DEBUG[8171]: chan_iax2.c:6618 socket_process: Received 
iseqno 4 not within window 5->5
[Mar 20 11:15:47] DEBUG[8171]: chan_iax2.c:7333 socket_process: Received 
VNAK: resending outstanding frames
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 002 Type: VOICE   Subclass: 8
   Timestamp: 00059ms  SCall: 00003  DCall: 00005 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: IAX     Subclass: VNAK
   Timestamp: 00165ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
[Mar 20 11:15:47] DEBUG[8172]: chan_iax2.c:6618 socket_process: Received 
iseqno 4 not within window 5->5
[Mar 20 11:15:47] DEBUG[8172]: chan_iax2.c:7333 socket_process: Received 
VNAK: resending outstanding frames
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 002 Type: VOICE   Subclass: 8
   Timestamp: 00059ms  SCall: 00003  DCall: 00005 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 005 Type: IAX     Subclass: ACK
   Timestamp: 00059ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: IAX     Subclass: VNAK
   Timestamp: 00168ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
[Mar 20 11:15:47] DEBUG[8173]: chan_iax2.c:6618 socket_process: Received 
iseqno 4 not within window 5->5
[Mar 20 11:15:47] DEBUG[8173]: chan_iax2.c:7333 socket_process: Received 
VNAK: resending outstanding frames
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 002 Type: VOICE   Subclass: 8
   Timestamp: 00059ms  SCall: 00003  DCall: 00005 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 005 Type: IAX     Subclass: ACK
   Timestamp: 00059ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 005 Type: IAX     Subclass: ACK
   Timestamp: 00059ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 005 Type: VOICE   Subclass: 8
   Timestamp: 00201ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
[Mar 20 11:15:47] DEBUG[8176]: chan_iax2.c:6649 socket_process: Ooh, 
voice format changed to 8
Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 003 Type: IAX     Subclass: ACK
   Timestamp: 00201ms  SCall: 00003  DCall: 00005 [192.168.52.94:4569]
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 005 Type: VOICE   Subclass: 8
   Timestamp: 00160ms  SCall: 00004  DCall: 00005 [192.168.52.95:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 004 Type: IAX     Subclass: ACK
   Timestamp: 00160ms  SCall: 00005  DCall: 00004 [192.168.52.95:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 005 Type: IAX     Subclass: 
TXREADY
   Timestamp: 02135ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
   CALL NUMBER     : 5

    -- Channel 'IAX2/0100101-3' ready to transfer
    -- Attempting media bridge of IAX2/0100101-3 and IAX2/0100201-4
Tx-Frame Retry[000] -- OSeqno: 005 ISeqno: 004 Type: IAX     Subclass: (38?)
   Timestamp: 02122ms  SCall: 00003  DCall: 00005 [192.168.52.94:4569]
   CALL NUMBER     : 5

Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 005 Type: IAX     Subclass: (38?)
   Timestamp: 02094ms  SCall: 00004  DCall: 00005 [192.168.52.95:4569]
   CALL NUMBER     : 5

Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 006 Type: IAX     Subclass: ACK
   Timestamp: 02122ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 005 Type: IAX     Subclass: ACK
   Timestamp: 02094ms  SCall: 00005  DCall: 00004 [192.168.52.95:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 005 Type: IAX     Subclass: TXREJ
   Timestamp: 07100ms  SCall: 00005  DCall: 00004 [192.168.52.95:4569]
    -- Channel 'IAX2/0100201-4' unable to transfer
Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 006 Type: IAX     Subclass: ACK
   Timestamp: 07100ms  SCall: 00004  DCall: 00005 [192.168.52.95:4569]
Tx-Frame Retry[000] -- OSeqno: 006 ISeqno: 004 Type: IAX     Subclass: TXREJ
   Timestamp: 07133ms  SCall: 00003  DCall: 00005 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 007 Type: IAX     Subclass: ACK
   Timestamp: 07133ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
[Mar 20 11:15:54] DEBUG[8204]: chan_iax2.c:3454 calc_timestamp: 
predicted timestamp skew (5020) > max (160), using real ts instead.
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 007 Type: IAX     Subclass: LAGRQ
   Timestamp: 10024ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
Tx-Frame Retry[000] -- OSeqno: 007 ISeqno: 005 Type: IAX     Subclass: LAGRP
   Timestamp: 10024ms  SCall: 00003  DCall: 00005 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 008 Type: IAX     Subclass: ACK
   Timestamp: 10024ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
Tx-Frame Retry[000] -- OSeqno: 008 ISeqno: 005 Type: IAX     Subclass: LAGRQ
   Timestamp: 10018ms  SCall: 00003  DCall: 00005 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 009 Type: IAX     Subclass: LAGRP
   Timestamp: 10018ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
Tx-Frame Retry[-01] -- OSeqno: 009 ISeqno: 006 Type: IAX     Subclass: ACK
   Timestamp: 10018ms  SCall: 00003  DCall: 00005 [192.168.52.94:4569]
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 005 Type: IAX     Subclass: LAGRQ
   Timestamp: 10028ms  SCall: 00005  DCall: 00004 [192.168.52.95:4569]
Tx-Frame Retry[000] -- OSeqno: 005 ISeqno: 006 Type: IAX     Subclass: LAGRQ
   Timestamp: 10029ms  SCall: 00004  DCall: 00005 [192.168.52.95:4569]
Tx-Frame Retry[000] -- OSeqno: 006 ISeqno: 007 Type: IAX     Subclass: LAGRP
   Timestamp: 10028ms  SCall: 00004  DCall: 00005 [192.168.52.95:4569]
Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 007 Type: IAX     Subclass: ACK
   Timestamp: 10028ms  SCall: 00005  DCall: 00004 [192.168.52.95:4569]
Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 006 Type: IAX     Subclass: LAGRP
   Timestamp: 10029ms  SCall: 00005  DCall: 00004 [192.168.52.95:4569]
[Mar 20 11:15:57] DEBUG[8173]: chan_iax2.c:6618 socket_process: Received 
iseqno 6 not within window 7->7
Tx-Frame Retry[-01] -- OSeqno: 006 ISeqno: 008 Type: IAX     Subclass: ACK
   Timestamp: 10029ms  SCall: 00004  DCall: 00005 [192.168.52.95:4569]
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 009 Type: IAX     Subclass: 
HANGUP
   Timestamp: 12486ms  SCall: 00005  DCall: 00003 [192.168.52.94:4569]
   CAUSE CODE      : 16

[Mar 20 11:15:59] DEBUG[8178]: chan_iax2.c:6944 socket_process: 
Immediately destroying 3, having received hangup
Tx-Frame Retry[-01] -- OSeqno: 009 ISeqno: 007 Type: IAX     Subclass: ACK
   Timestamp: 12486ms  SCall: 00003  DCall: 00005 [192.168.52.94:4569]
[Mar 20 11:15:59] DEBUG[8204]: chan_iax2.c:2937 iax2_hangup: We're 
hanging up IAX2/0100201-4 now...
    -- Hungup 'IAX2/0100201-4'
  == Spawn extension (default, 12, 2) exited non-zero on 'IAX2/0100101-3'
Tx-Frame Retry[000] -- OSeqno: 007 ISeqno: 008 Type: IAX     Subclass: 
HANGUP
   Timestamp: 12467ms  SCall: 00004  DCall: 00005 [192.168.52.95:4569]
   CAUSE CODE      : 16

Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 008 Type: IAX     Subclass: ACK
   Timestamp: 12467ms  SCall: 00005  DCall: 00004 [192.168.52.95:4569]
[Mar 20 11:15:59] DEBUG[8204]: cdr_addon_mysql.c:210 mysql_log: 
cdr_mysql: inserting a CDR record.
[Mar 20 11:15:59] DEBUG[8204]: cdr_addon_mysql.c:226 mysql_log: 
cdr_mysql: SQL command as follows: INSERT INTO cdr 
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield) 
VALUES ('2007-03-20 11:15:47','0100101','0100101','12','default', 
'IAX2/0100101-3','IAX2/0100201-4','Dial','IAX2/server:pwd at 0100201/12',12,12,'ANSWERED',3,'','')
[Mar 20 11:15:59] DEBUG[8204]: chan_iax2.c:2937 iax2_hangup: We're 
hanging up IAX2/0100101-3 now...
[Mar 20 11:15:59] DEBUG[8204]: chan_iax2.c:2947 iax2_hangup: Really 
destroying IAX2/0100101-3 now...
    -- Hungup 'IAX2/0100101-3'

*CLI> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     
Subclass: REGREQ
   Timestamp: 00006ms  SCall: 00006  DCall: 00000 [192.168.52.95:4569]
   USERNAME        : 0100201
   REFRESH         : 60

Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: 
REGACK
   Timestamp: 00007ms  SCall: 00005  DCall: 00006 [192.168.52.95:4569]
   USERNAME        : 0100201
   DATE TIME       : 2007-03-20  11:16:02
   REFRESH         : 60
   APPARENT ADDRES : IPV4 192.168.52.95:4569
   CALLING NUMBER  : 0100201

Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: ACK
   Timestamp: 00007ms  SCall: 00006  DCall: 00005 [192.168.52.95:4569]



More information about the asterisk-users mailing list