[Home]

Summary:ASTERISK-04639: IAX2 one way audio with jitterbuffer = on
Reporter:Martin Vit (festr)Labels:
Date Opened:2005-07-20 15:26:45Date Closed:2005-07-25 19:24:09
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_iax2
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:I have two asterisk boxes. On A is E1, box B has TDM400P. I have done little test. Route call through A(E1) to box B to application milliwatt. When jitterbuffer=yes (trunk=off) is set, audio from milliwatt will freez after two seconds. The same situation with SIP registered to B, audio from SIP will freez, RX audio in SIP is ok. This i can reproduce anytime i call. Codec was ilbc.
kernel 2.6.11 on both. CVS HEAD 20.7.2005, timers correctly loaded from zaptel drivers.

****** ADDITIONAL INFORMATION ******

this is debug from box B

   -- Executing Milliwatt("IAX2/xxxxxxxxxxxx:4569-1", "") in new stack
Jul 20 22:09:24 DEBUG[2784]: channel.c:2006 set_format: Set channel IAX2/aSt-tacoMa@213.194.206.194:4569-1 to write format ulaw
Jul 20 22:09:24 DEBUG[2784]: channel.c:2006 set_format: Set channel IAX2/aSt-tacoMa@213.194.206.194:4569-1 to read format ulaw
Jul 20 22:09:24 DEBUG[2784]: channel.c:1375 ast_settimeout: Scheduling timer at 160 sample intervals
Jul 20 22:09:24 DEBUG[2784]: app_queue.c:426 changethread: Device 'IAX2/aSt' changed to state '4' (Invalid)
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 2, (6, 4)
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:6445 socket_read: Cancelling transmission of packet 1
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:6542 socket_read: IAX subclass 4 received
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 2, (6, 4)
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:6445 socket_read: Cancelling transmission of packet 2
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:6542 socket_read: IAX subclass 4 received
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 2, (2, 1024)
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:6501 socket_read: Ooh, voice format changed to 1024
Jul 20 22:09:24 DEBUG[2784]: channel.c:2006 set_format: Set channel IAX2/aSt-tacoMa@213.194.206.194:4569-1 to read format ulaw
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:7429 socket_read: For call=1, set last=120
Jul 20 22:09:24 DEBUG[2784]: channel.c:1637 ast_read: Generator got voice, switching to phase locked mode
Jul 20 22:09:24 DEBUG[2784]: channel.c:1375 ast_settimeout: Scheduling timer at 0 sample intervals
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:7429 socket_read: For call=1, set last=150
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:3444 calc_timestamp: predicted timestamp skew (180) > max (160), using real ts instead.
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 2, (6, 4)
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:6445 socket_read: Cancelling transmission of packet 3
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:6542 socket_read: IAX subclass 4 received
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 0, last = 150)
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 30, last = 150)
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 60, last = 150)
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 90, last = 150)
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 120, last = 150)
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:3444 calc_timestamp: predicted timestamp skew (1717987112) > max (160), using real ts instead.
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 150, last = 150)
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 3, (6, 4)
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:6445 socket_read: Cancelling transmission of packet 4
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:6542 socket_read: IAX subclass 4 received
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 3, (2, 1024)
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:7429 socket_read: For call=1, set last=1717987320
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:3444 calc_timestamp: predicted timestamp skew (429496756) > max (160), using real ts instead.
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:7429 socket_read: For call=1, set last=1717987350
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 4, (6, 4)
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:6445 socket_read: Cancelling transmission of packet 5
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:6542 socket_read: IAX subclass 4 received
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 4, (2, 1024)
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1288490670, last = 1717987350)
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:3444 calc_timestamp: predicted timestamp skew (429496740) > max (160), using real ts instead.
Jul 20 22:09:24 DEBUG[2784]: chan_iax2.c:7429 socket_read: For call=1, set last=1718013644
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 5, (6, 4)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6445 socket_read: Cancelling transmission of packet 6
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6542 socket_read: IAX subclass 4 received
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 5, (2, 1024)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 858993990, last = 1718013644)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:3444 calc_timestamp: predicted timestamp skew (429496731) > max (160), using real ts instead.
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1717974372, last = 1718013644)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 6, (6, 4)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6445 socket_read: Cancelling transmission of packet 7
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6542 socket_read: IAX subclass 4 received
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 6, (2, 1024)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 429497340, last = 1718013644)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:3444 calc_timestamp: predicted timestamp skew (429496742) > max (160), using real ts instead.
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1718000666, last = 1718013644)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 7, (6, 4)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6445 socket_read: Cancelling transmission of packet 8
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6542 socket_read: IAX subclass 4 received
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 7, (2, 1024)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 660, last = 1718013644)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:3444 calc_timestamp: predicted timestamp skew (660) > max (160), using real ts instead.
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1717961394, last = 1718013644)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:2069 unwrap_timestamp: schedule_delivery: pushed forward timestamp
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7429 socket_read: For call=1, set last=1718026930
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1718026240, last = 1718026930)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1718026270, last = 1718026930)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1718026300, last = 1718026930)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1718026330, last = 1718026930)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1718026360, last = 1718026930)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:3444 calc_timestamp: predicted timestamp skew (1717987626) > max (160), using real ts instead.
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1718026390, last = 1718026930)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 8, (6, 4)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6445 socket_read: Cancelling transmission of packet 9
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6542 socket_read: IAX subclass 4 received
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 8, (2, 1024)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1717987890, last = 1718026930)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:3444 calc_timestamp: predicted timestamp skew (429496750) > max (160), using real ts instead.
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7429 socket_read: For call=1, set last=1718053456
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 9, (6, 4)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6445 socket_read: Cancelling transmission of packet 10
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6542 socket_read: IAX subclass 4 received
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 9, (2, 1024)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1288491210, last = 1718053456)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:3444 calc_timestamp: predicted timestamp skew (429496734) > max (160), using real ts instead.
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7429 socket_read: For call=1, set last=1718079720
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 10, (6, 4)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6445 socket_read: Cancelling transmission of packet 11
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6542 socket_read: IAX subclass 4 received
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 10, (2, 1024)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 858994530, last = 1718079720)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:3444 calc_timestamp: predicted timestamp skew (429496752) > max (160), using real ts instead.
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1718040448, last = 1718079720)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 11, (6, 4)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6445 socket_read: Cancelling transmission of packet 12
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6542 socket_read: IAX subclass 4 received
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 11, (2, 1024)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 429497880, last = 1718079720)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:3444 calc_timestamp: predicted timestamp skew (429496736) > max (160), using real ts instead.
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1718066742, last = 1718079720)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 12, (6, 4)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6445 socket_read: Cancelling transmission of packet 13
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6542 socket_read: IAX subclass 4 received
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 12, (2, 1024)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1200, last = 1718079720)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:3444 calc_timestamp: predicted timestamp skew (1230) > max (160), using real ts instead.
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1718027470, last = 1718079720)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:2069 unwrap_timestamp: schedule_delivery: pushed forward timestamp
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7429 socket_read: For call=1, set last=1718093006
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1718091776, last = 1718093006)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1718091806, last = 1718093006)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1718091836, last = 1718093006)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1718091866, last = 1718093006)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1718091896, last = 1718093006)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:3444 calc_timestamp: predicted timestamp skew (1717988174) > max (160), using real ts instead.
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1718091926, last = 1718093006)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 13, (6, 4)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6445 socket_read: Cancelling transmission of packet 14
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6542 socket_read: IAX subclass 4 received
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 13, (2, 1024)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1717988430, last = 1718093006)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:3444 calc_timestamp: predicted timestamp skew (429496738) > max (160), using real ts instead.
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7429 socket_read: For call=1, set last=1718119532
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 14, (6, 4)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6445 socket_read: Cancelling transmission of packet 15
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6542 socket_read: IAX subclass 4 received
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 14, (2, 1024)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1288491750, last = 1718119532)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:3444 calc_timestamp: predicted timestamp skew (429496758) > max (160), using real ts instead.
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7429 socket_read: For call=1, set last=1718145796
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 15, (6, 4)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6445 socket_read: Cancelling transmission of packet 16
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6542 socket_read: IAX subclass 4 received
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 15, (2, 1024)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 858995100, last = 1718145796)
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:3444 calc_timestamp: predicted timestamp skew (429496744) > max (160), using real ts instead.
Jul 20 22:09:25 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1718106554, last = 1718145796)
Jul 20 22:09:26 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 16, (2, 1024)
Jul 20 22:09:26 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 429498420, last = 1718145796)
Jul 20 22:09:26 DEBUG[2784]: chan_iax2.c:3444 calc_timestamp: predicted timestamp skew (429496727) > max (160), using real ts instead.
Jul 20 22:09:26 DEBUG[2784]: chan_iax2.c:6348 socket_read: Received packet 16, (6, 4)
Jul 20 22:09:26 DEBUG[2784]: chan_iax2.c:6445 socket_read: Cancelling transmission of packet 17
Jul 20 22:09:26 DEBUG[2784]: chan_iax2.c:6542 socket_read: IAX subclass 4 received
Jul 20 22:09:26 DEBUG[2784]: chan_iax2.c:7404 socket_read: Received out of order packet... (type=2, subclass 1024, ts = 1718132818, last = 1718145796)
Comments:By: Steve Davies . (stevedavies) 2005-07-20 16:31:01

this is a duplicate of bg 4747.

I've just figured out the cause.  Just trying to work out the bext fix.   Look for a patch posted in bug 4747 tomorrow.

Steve
By: Kevin P. Fleming (kpfleming) 2005-07-20 18:43:06

This is probably the same problem as reported in bug ASTERISK-4704747, you should have searched the open bugs a little more thoroughly.
By: Martin Vit (festr) 2005-07-21 11:51:33

problems went away after the latest patch, but new there is other problems. The same testing boxes. When do SIP call from asterisk B to asterisk A to application Echo, no sound is coming to me (this is for every call). When do sip call B -> A(E1). 50% of all tests have problem with one-way audio (user behind E1 hear anything). If jitterbuffer = off (on box A) everything is ok.

no strange debug releated to this so i dont know what to look for.
By: Michael Jerris (mikej) 2005-07-21 11:56:24

what does any of this have to do with iax, your explanation does not include any iax connections.
By: Martin Vit (festr) 2005-07-21 12:02:01

ok sorry for not exactly explanation.

SIP phone -> register -> asterisk box B -> IAX -> asterisk box A with E1 -> world

calling from B to A over IAX. When jitter=on on box A there is problem which i decribed. When jitter = off everything work fine.


By: Martin Vit (festr) 2005-07-21 18:30:26

i've done some more tests and i forgot, that my A and B asterisks are connected through next asterisk C. So complete scenario is:

SIP -> [asterisk B] -iax-> [asterisk C] -iax-> [asterisk A(E1)]

so the media stream B -> C -> A  is transfered directly between B -> A. When i turn on in iax.conf notransfer=yes so media stream is not tranfered and go through box C everything work (with jitter=on on box A). It doesnt matter if C is asterisk stable or latest HEAD CVS. Somethink is wrong in combination IAX transfer and jitterbuffer=on.
By: Kevin P. Fleming (kpfleming) 2005-07-25 19:23:27

Please open a new bug and work with the bug marshals in the #asterisk IRC channel to produce the proper debugging information required, since your configuration is quite complex.