| 00:19.49 | *** join/#asterisk-dev infobot (ibot@208.53.50.136) |
| 00:19.49 | *** topic/#asterisk-dev is Asterisk Development Discussion -=- http://www.asterisk.org/developers -=- Tier 2 and 3.14159265 support is in #asterisk -=- Check out our blog! blogs.asterisk.org -=- Follow on Twitter at @AsteriskDev |
| 00:59.05 | *** join/#asterisk-dev snuff-work (~snuff-wor@210.9.148.102) |
| 00:59.05 | *** mode/#asterisk-dev [+o snuff-work] by ChanServ |
| 01:52.58 | *** join/#asterisk-dev awkwardpenguin (~awkwardpe@cpe-172-118-246-147.socal.res.rr.com) |
| 02:45.13 | DanFromUK | Hi. I've got a Local Channel that is performing Dial(AnotherLocalChannel/n,5,t). When it times out, ${CDR(duration)} appears to be Zero. Is this expected or could it be a bug that I should report? |
| 03:18.49 | *** join/#asterisk-dev awkwardpenguin (~awkwardpe@cpe-172-118-246-147.socal.res.rr.com) |
| 03:39.16 | *** join/#asterisk-dev awkwardpenguin (~awkwardpe@cpe-172-118-246-147.socal.res.rr.com) |
| 04:40.57 | *** join/#asterisk-dev awkwardpenguin (~awkwardpe@cpe-172-118-246-147.socal.res.rr.com) |
| 04:52.12 | *** join/#asterisk-dev awkwardpenguin (~awkwardpe@cpe-172-118-246-147.socal.res.rr.com) |
| 05:47.21 | *** join/#asterisk-dev fblackburn (~fblackbur@modemcable094.94-70-69.static.videotron.ca) |
| 06:10.03 | *** join/#asterisk-dev tsearle (~tsearle@37.19.10.33) |
| 06:10.03 | *** mode/#asterisk-dev [+o tsearle] by ChanServ |
| 07:24.14 | *** join/#asterisk-dev jkroon (~jkroon@165.16.203.126) |
| 08:33.51 | *** join/#asterisk-dev hehol (~hehol@gatekeeper.loca.net) |
| 19:20.09 | *** join/#asterisk-dev infobot (ibot@208.53.50.136) |
| 19:20.09 | *** topic/#asterisk-dev is Asterisk Development Discussion -=- http://www.asterisk.org/developers -=- Tier 2 and 3.14159265 support is in #asterisk -=- Check out our blog! blogs.asterisk.org -=- Follow on Twitter at @AsteriskDev |
| 19:54.47 | *** join/#asterisk-dev rustlebee (~rustlebee@redhat/russellb) |
| 19:54.48 | *** mode/#asterisk-dev [+o rustlebee] by ChanServ |
| 19:57.52 | NirS_ | @seanbright, I think this one is for you |
| 19:58.03 | NirS_ | we upgraded to 15.5.0 |
| 19:58.14 | NirS_ | and we're using your Opus patch in the system |
| 19:58.22 | NirS_ | and here is what happens |
| 19:58.33 | NirS_ | at an unknown time, the following happens: |
| 19:58.45 | NirS_ | [Aug 20 19:56:11] NOTICE[13252][C-00000002]: translate.c:594 ast_translate: 24380 lost frame(s) 0/41154 (opus@48000)->(slin@48000) |
| 19:58.45 | NirS_ | [Aug 20 19:56:11] WARNING[13252][C-00000002]: channel.c:1136 __ast_queue_frame: Exceptionally long queue length queuing to SIP/subscribers.prod2.cx.glowbie.com-00000002 |
| 19:59.24 | NirS_ | after the second warning, Asterisk no longer sends packets the originated from the IP phone that uses Opus, however, it is fully capable of receiving audio |
| 20:00.21 | NirS_ | we also tried converting to DAHDI timer, but that yielded the exact same results |
| 20:02.15 | NirS_ | @sean you can see a full logger trace here https://clbin.com/XzguU |
| 21:05.56 | seanbright | NirS_: stop using 'my' opus patch - it's garbage |
| 21:06.03 | seanbright | relatively speaking |
| 21:06.06 | seanbright | use digium's |
| 21:06.20 | seanbright | use dnsmasq to stop the phoning home if you're the paranoid type |
| 21:06.32 | seanbright | but that may void your warranty |
| 21:24.20 | NirS_ | that's just what we did right now |
| 21:24.26 | seanbright | good good |
| 21:24.34 | NirS_ | but the issue persists exactly the same |
| 21:24.37 | seanbright | i would _never_ use code that i wrote in production |
| 21:24.44 | NirS_ | good one |
| 21:25.00 | NirS_ | here is what we are seeing |
| 21:25.46 | NirS_ | https://clbin.com/8Tu2l |
| 21:26.02 | NirS_ | this is using the Digium Opus codec |
| 21:26.30 | NirS_ | you see normal traffic, then suddenly: |
| 21:26.30 | NirS_ | [Aug 20 21:22:32] DEBUG[16494][C-00000003]: translate.c:756 ast_translate: Sample size different 160 vs 960 |
| 21:26.30 | NirS_ | Got RTP packet from 167.99.2.76:15396 (type 08, seq 049716, ts 1727263688, len 000160) |
| 21:26.30 | NirS_ | [Aug 20 21:22:32] DEBUG[16494][C-00000003]: translate.c:756 ast_translate: Sample size different 160 vs 960 |
| 21:26.31 | NirS_ | Got RTP packet from 167.99.2.76:15396 (type 08, seq 049717, ts 1727263848, len 000160) |
| 21:26.33 | NirS_ | [Aug 20 21:22:32] DEBUG[16494][C-00000003]: translate.c:756 ast_translate: Sample size different 160 vs 960 |
| 21:26.36 | NirS_ | Got RTP packet from 167.99.2.76:15396 (type 08, seq 049718, ts 1727264008, len 000160) |
| 21:26.37 | seanbright | k |
| 21:26.38 | NirS_ | [Aug 20 21:22:32] DEBUG[16494][C-00000003]: translate.c:756 ast_translate: Sample size different 160 vs 960 |
| 21:26.40 | seanbright | K |
| 21:26.41 | NirS_ | [Aug 20 21:22:32] WARNING[16491][C-00000003]: channel.c:1136 __ast_queue_frame: Exceptionally long queue length queuing to SIP/subscribers.prod2.cx.glowbie.com-00000004 |
| 21:26.42 | seanbright | K! |
| 21:26.44 | NirS_ | [Aug 20 21:22:32] WARNING[16491][C-00000003]: res_format_attr_opus.c:337 opus_set: unknown attribute type ptime |
| 21:26.47 | NirS_ | Sent RTP packet to 18.205.100.13:32192 (type 107, seq 036943, ts 31177968, len 000003) |
| 21:26.49 | NirS_ | Sent RTP packet to 167.99.2.76:15396 (type 08, seq 054719, ts 5217456, len 000160) |
| 21:26.51 | *** kick/#asterisk-dev [NirS_!~sean@asterisk/community-developer/seanbright] by seanbright (come back later) |
| 21:27.16 | *** join/#asterisk-dev NirS_ (~Nir_S@141.226.192.98) |
| 21:27.29 | NirS_ | yeah, too many lines in there, sorry |
| 21:27.33 | seanbright | no problem |
| 21:28.22 | NirS_ | what do you think? |
| 21:28.33 | seanbright | me? |
| 21:28.35 | seanbright | i have no idea |
| 21:28.50 | seanbright | seems like something bad is happening... |
| 21:28.52 | seanbright | heh |
| 21:28.59 | NirS_ | really? |
| 21:29.22 | seanbright | i don't really know anything about opus |
| 21:30.02 | NirS_ | I see |
| 21:30.08 | seanbright | i kinda knew how to use the libopus API, but what goes on the wire and all that... not much |
| 21:30.13 | NirS_ | ok, maybe one of the other devs here have an idea |
| 21:30.36 | NirS_ | I don't think this has anything to do with the actual wireline codec |
| 21:30.42 | NirS_ | I think this is something in the transcoder |
| 21:30.44 | seanbright | an issue on issues.asterisk.org with a pcap might help |
| 21:31.12 | file | as well as a backtrace ... |
| 21:31.57 | NirS_ | @file, Asterisk doesn't crash or core-dumps |
| 21:32.06 | file | you can get a backtrace from a running process. |
| 21:32.28 | NirS_ | what's the procedure ? |
| 21:32.30 | file | <PROTECTED> |
| 21:33.47 | NirS_ | that's exactly the thing - it doesn't look like a dead-lock or something like that |
| 21:34.02 | file | it's better to provide more information than not |
| 21:34.09 | NirS_ | I guess |
| 21:34.18 | file | for example, the queue message generally occurs when there is a deadlock on the thread reading from the channel |
| 21:34.37 | NirS_ | anyone can explain to me what this means (in the technical level): [Aug 20 21:22:32] NOTICE[16491][C-00000003]: translate.c:594 ast_translate: 17143 lost frame(s) 0/48391 (opus@48000)->(slin@48000) |
| 21:34.46 | file | so if that is the case then a backtrace would show it |
| 21:34.48 | NirS_ | this happens right before everything goes to sh** |
| 21:35.08 | seanbright | i assume there is a sequence number gap |
| 21:35.18 | seanbright | but i could be making that up |
| 21:35.32 | NirS_ | amusing |
| 21:35.45 | file | that message does not appear in our codebase |
| 21:35.52 | seanbright | ohhh |
| 21:35.57 | seanbright | JACKPOT |
| 21:39.22 | seanbright | NirS_: that is here: https://github.com/traud/asterisk-opus/blob/asterisk-13.7/enable_native_plc.patch |
| 21:39.25 | seanbright | you should roll that out |
| 21:40.04 | seanbright | actually, you should try with vanilla asterisk, otherwise it's hard for us to guess what could be broken between asterisk code & third-party code |
| 21:42.07 | NirS_ | ok, odd, don't remember applying that in |
| 21:42.56 | seanbright | might want to start over from a fresh tarball |
| 21:43.09 | seanbright | or 'git checkout -- . ; git clean -dfx' if you are using git |
| 21:44.20 | NirS_ | 10-4 |
| 22:03.16 | NirS_ | well, I'll post results tomorrow - time to go home now |
| 22:03.18 | NirS_ | it's 1AM |
| 23:20.37 | *** part/#asterisk-dev kharwell (kharwell@nat/digium/x-ljlntxmhpgbgglgp) |