| 00:21.14 | *** join/#asterisk-dev infobot (ibot@rikers.org) |
| 00:21.14 | *** 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 |
| 01:53.39 | *** join/#asterisk-dev newtonr_ (~newtonr@173-21-147-197.client.mchsi.com) |
| 01:53.39 | *** mode/#asterisk-dev [+o newtonr_] by ChanServ |
| 04:37.18 | *** join/#asterisk-dev coreyfarrell (~coreyfarr@24-177-86-98.dhcp.nwtn.ct.charter.com) |
| 04:37.18 | *** mode/#asterisk-dev [+o coreyfarrell] by ChanServ |
| 04:39.54 | *** join/#asterisk-dev libardi (~libardi@187.64.228.189) |
| 06:50.45 | *** join/#asterisk-dev pchero_work (~pchero@109.70.54.56) |
| 06:52.49 | *** join/#asterisk-dev tsearle (~tsearle@37.19.10.33) |
| 06:59.52 | *** join/#asterisk-dev tsearle (~tsearle@37.19.10.33) |
| 07:04.23 | *** join/#asterisk-dev wdoekes (~walter@wjd.osso.nl) |
| 07:04.23 | *** mode/#asterisk-dev [+o wdoekes] by ChanServ |
| 07:09.32 | *** join/#asterisk-dev tzafrir (~tzafrir@local.xorcom.com) |
| 07:09.32 | *** mode/#asterisk-dev [+o tzafrir] by ChanServ |
| 07:31.20 | *** join/#asterisk-dev stefan27 (~stefan27@static-212-247-4-149.cust.tele2.se) |
| 07:35.36 | *** join/#asterisk-dev hehol (~hehol@gatekeeper.loca.net) |
| 07:51.54 | *** join/#asterisk-dev bof22 (~Thunderbi@ARennes-650-1-246-146.w2-14.abo.wanadoo.fr) |
| 07:52.21 | *** join/#asterisk-dev jkroon (~jkroon@165.255.15.80) |
| 08:16.17 | *** join/#asterisk-dev tuxd00d (~tuxd00d@ip68-106-11-138.ph.ph.cox.net) |
| 08:44.35 | stefan27 | Hi asterisk, I've seen an increasing number of warning messages "channel.c: Exceptionally long voice queue length queuing to ..." after upgrading from 13.5 to 13.15. We cannot yet directly link these warnings to concrete issue reports, but I query asterisk-JIRA for these warnings and found a lot of tickets that had been closed unresolved due to lack of activity... |
| 08:45.52 | stefan27 | In my cases it seems to only happen when app_queue places calls to agents that are local channels (which in turn dial agent's chan_sip devices/peers) |
| 08:46.20 | stefan27 | I'm trying to first understand what this warning means |
| 08:48.26 | stefan27 | ast_queue_frame "Queue one or more frames to a channel's frame queue" ; I guess it would help to print the contents of this queue when it is exceptionally long |
| 09:01.19 | snuff-work | it is probably queuing up audio while it searches via local channel, but i could be totally wrong.. |
| 09:13.41 | *** join/#asterisk-dev tsearle (~tsearle@37.19.10.33) |
| 09:17.47 | *** join/#asterisk-dev cresl1n (~Adium@asterisk/libpri-and-libss7-expert/Cresl1n) |
| 09:17.47 | *** mode/#asterisk-dev [+o cresl1n] by ChanServ |
| 09:31.06 | *** join/#asterisk-dev jkroon (~jkroon@165.16.204.34) |
| 09:41.20 | *** join/#asterisk-dev X-Rob (sid14615@gateway/web/irccloud.com/x-azdyagupcmpigpzd) |
| 09:49.08 | *** join/#asterisk-dev tsearle (~tsearle@37.19.10.33) |
| 10:02.00 | stefan27 | I'll get back with more info within a few hours |
| 10:08.00 | file | you can't really print the contents of the queue, as it's usually media frames |
| 10:09.01 | file | and I haven't seen anything recent filed like that |
| 11:30.10 | tsearle | https://www.youtube.com/watch?v=18kV4WJSRRg&feature=youtu.be&a |
| 11:30.20 | tsearle | kamailio world live stream |
| 12:15.14 | stefan27 | I tried to summarize the setup with this picture https://postimg.org/image/a13n3gd5h/ also a simplified view with https://postimg.org/image/ofbksdygf/ |
| 12:15.44 | stefan27 | The main problem for me is I can't reproduce the "issues"/the warning messages in my test asterisk |
| 12:20.03 | file | the message itself means that a thread is either deadlocked or isn't reading frames from the channel, a backtrace would illuminate things |
| 12:20.49 | tsearle | can't you also enable deadlock detection in the build process? |
| 12:21.17 | stefan27 | it seems the local channel that the error message refers to is typically optimized out upon answering |
| 12:21.47 | stefan27 | Does that mean that the deadlock/queue overflow probably occurs during the ringing phase? |
| 12:23.45 | file | maybe? |
| 12:23.56 | file | tsearle: you can enable debugging... but it has a high penalty |
| 12:26.30 | stefan27 | Sorry for the messy environment here, but refering to my first picture, Local_y;1 is spawned by something in app_queue.c and Local_y;2 executes Dial to another local channel (Local_q)... How many threads are at play here, i.e. which threads read and write frames to Local_y at this stage? |
| 12:26.51 | stefan27 | Once I can reproduce this issue, I can get a backtrace |
| 12:27.14 | file | 4 threads? |
| 12:27.44 | *** join/#asterisk-dev scgm11_ (~scgm11@r186-52-93-184.dialup.adsl.anteldata.net.uy) |
| 12:27.58 | file | second thread in from left would be queueing for first thread from left to read |
| 12:28.14 | file | soooooo it'd be app_queue not reading |
| 12:33.07 | stefan27 | Trying to interpret what you said in my own world - Refering to my second picture, that'd be the pbx-thread from SIP_X that executed app_queue.c's try_calling? Some other threads put frames onto that tmp->chan we create, but that pbx-thread is not reading them? |
| 12:34.11 | stefan27 | (I'm aware we are just guessing here until we have a reproducable case) |
| 12:38.45 | stefan27 | there's only a single queue that stores all frames written to a channel? |
| 12:44.18 | file | writing to a channel is different from queueing |
| 12:44.23 | file | there is only a single queue for queued frames |
| 12:44.26 | stefan27 | There's big gaps in my understanding of the thread-channel model especially when bridges join the fray |
| 12:44.45 | stefan27 | ah |
| 12:44.54 | file | and yes |
| 12:45.06 | file | the pbx-thread is not reading them, but in that thread it is app_queue that is executing |
| 12:45.09 | file | and it is reasonable for reading |
| 12:47.44 | stefan27 | I mentioned that I have found unresolved closed jiras earlier about these warning messages earlier not to signal that many other users have same issue, but rather that it seems difficult to provide enough information in a jira regarding this to make it debug-able |
| 12:48.43 | file | a backed up queue is generally a symptom of something else |
| 12:48.55 | file | so isolating what the specific problem is is difficult |
| 12:48.57 | stefan27 | the presence of a warning message doesn't say much about the cause... I'd need sip-traces and preferably a backtrace coredump --- for that I should patch asterisk to produce a coredump instead of writing that log message to file? |
| 12:50.59 | stefan27 | If I go through that trouble, do you know any other helpful debugging steps, should core debug be 5 and i need to recompile with DEBUG_THREADS or whichever that enabled logging of locks? |
| 12:51.30 | file | DEBUG_THREADS would probably show it |
| 12:51.33 | file | your performance would just tak |
| 12:51.35 | file | er tank |
| 12:51.41 | file | and if the problem is timing dependent, then it can alter that |
| 12:52.05 | stefan27 | right, that's a big issue then; let me think for a while |
| 12:52.24 | tsearle | why do you need to modify asterisk to produce a core? can't you just kill asterisk and force a core? |
| 12:52.39 | tsearle | e.g. kill -6 or the likes |
| 12:52.41 | file | you can also just attach gdb and get a backtrace |
| 12:53.02 | stefan27 | If i can reproduce it reliably in a test environment I can do either of that yes |
| 12:53.19 | stefan27 | but at the moment it only happens 5-6 times a day per production asterisk |
| 12:53.47 | stefan27 | in which case the call is not established anyways, it would not hurt them much to take one server and make it crash when the symtom appears |
| 12:55.14 | stefan27 | if it's load related I just need to configure calling robots in the test environment again |
| 12:57.47 | stefan27 | first subtle issue ive had that was unrelated to webrtc :) |
| 13:05.46 | stefan27 | One of the jiras I was refering to was https://issues.asterisk.org/jira/browse/ASTERISK-26956?jql=text%20~%20%22Exceptionally%20long%20voice%22%20ORDER%20BY%20created%20DESC but he closed it himself after the symtoms disappered magically after changing something externally with ports |
| 13:08.29 | tsearle | is there away to get the IP address of asterisk from the dial plan? e.g. to do Transfer(SIP/echo@${My_IP_ADDRESS}) |
| 13:08.52 | tsearle | wan't to do a REFER callflow test w/o hardcoding the IP address |
| 13:09.46 | file | stefan27: *nod* |
| 13:10.02 | file | tsearle: um you could use SYSTEM... otherwise don't think so |
| 13:11.47 | *** join/#asterisk-dev scgm11__ (~scgm11@r186-52-220-24.dialup.adsl.anteldata.net.uy) |
| 13:11.47 | stefan27 | we use a global dialplan variable for those kind of things. e.g in extensions.conf [globals] we do #exec /var/lib/asterisk/scripts/create-globalvars.pl |
| 13:11.59 | stefan27 | and a script that extracts system globals |
| 13:12.15 | stefan27 | like OWN_DOMAIN_REGEX or OWN_DOMAIN_IPV4 and yadda yadda |
| 13:12.30 | tsearle | we have a similar hack like that already |
| 13:12.41 | tsearle | we add HOSTNAME=$HOSTNAME in the init script |
| 13:12.52 | tsearle | so that $ENV(HOSTNAME) works |
| 13:13.33 | tsearle | for some reason, despite $HOSTNAME looking & feeling like an env var, it isn't a real one and ast can't see it out of the box |
| 13:36.54 | *** join/#asterisk-dev scgm11_ (~scgm11@r186-52-220-24.dialup.adsl.anteldata.net.uy) |
| 13:48.36 | *** join/#asterisk-dev putnopvut (putnopvut@asterisk/master-of-queues/mmichelson) |
| 13:48.36 | *** mode/#asterisk-dev [+o putnopvut] by ChanServ |
| 13:52.20 | *** join/#asterisk-dev rmudgett (rmudgett@nat/digium/x-wtuosfpocuwpcfkj) |
| 13:52.20 | *** mode/#asterisk-dev [+o rmudgett] by ChanServ |
| 13:59.38 | *** join/#asterisk-dev scgm11_ (~scgm11@r186-50-166-173.dialup.adsl.anteldata.net.uy) |
| 14:12.10 | stefan27 | Hi putnopvut, if you're interested in following up ASTERISK-26982 as it relates to the RTCP MUX support you may have been involved in, I have a question regarding the behavior of ast_rtp_ice_start: Should we not discard remote RTCP ice candidates in that while loop if rtp->ice_num_components == 1 ? There's a already comment later in that function that says we don't care about the lack of |
| 14:12.10 | stefan27 | RTCP candidates if there is only one ICE component. |
| 14:13.00 | putnopvut | has a look |
| 14:15.01 | stefan27 | The thing is that firefox always sends RTCP ice candidates in their SDP even though it supports rtcp-mux; in chrome one can set rtcpMuxPolicy to require which makes chrome remove the RTCP ice candidates from the SDP. In time firefox will probably do the same, but for now we have that JIRA |
| 14:16.08 | putnopvut | stefan27: Out of curiosity, are you using chan_sip or chan_pjsip in Asterisk? I ask because from what I see with chan_pjsip, we should be filtering out the remote RTCP candidates at the SDP level before we ever call ast_rtp_ice_start(). But the logic could be flawed. I'm not sure if chan_sip is doing the same thing. |
| 14:16.38 | stefan27 | Aha, yes I'm sorry we tried to find someone last week that could test it on pjsip, but I only produced this issue using chan_sip |
| 14:17.27 | file | putnopvut: neat |
| 14:17.28 | putnopvut | All right. So in chan_pjsip's SDP-handling, we iterate over the remote ICE candidates, and at that level, we filter out the RTCP candidates. It sounds like the same thing should probably be done in chan_sip. |
| 14:18.22 | putnopvut | Yeah, looking at process_sdp_a_ice() in chan_sip, it looks like it's not doing that sort of filtering |
| 14:19.41 | stefan27 | pjsip filters out RTCP candidates from SDP if both asterisk and client support rtcp_mux? |
| 14:20.06 | putnopvut | That is correct |
| 14:20.43 | putnopvut | Sorry for the paste here but it's only a few lines |
| 14:20.47 | putnopvut | <PROTECTED> |
| 14:20.47 | putnopvut | <PROTECTED> |
| 14:20.47 | putnopvut | <PROTECTED> |
| 14:20.47 | putnopvut | <PROTECTED> |
| 14:20.47 | putnopvut | <PROTECTED> |
| 14:20.49 | putnopvut | <PROTECTED> |
| 14:21.25 | putnopvut | The if conditions are |
| 14:21.30 | putnopvut | * We support RTCP MUX |
| 14:21.33 | putnopvut | * They support RTCP MUX |
| 14:21.49 | putnopvut | * The ICE candidate ID is > 1 |
| 14:22.09 | stefan27 | what is "candidate.id" here? |
| 14:23.08 | *** join/#asterisk-dev kharwell (kharwell@nat/digium/x-zxpkhvokbasavfpu) |
| 14:23.08 | *** mode/#asterisk-dev [+o kharwell] by ChanServ |
| 14:23.35 | stefan27 | I have not studied the ICE specs; I just empirically found the issue and the related conditions |
| 14:23.42 | putnopvut | If you want to have a look at res/res_pjsip_sdp_rtp.c, the function is process_ice_attributes(). We have a struct ast_rtp_engine_ice_candidate called "candidate" that is parsed from the ice candidate SDP line |
| 14:24.05 | putnopvut | So candidate.id is either 1 for RTP, or 2 for RTCP. |
| 14:24.17 | file | aka component ID |
| 14:24.17 | stefan27 | aha, so component id? |
| 14:24.20 | putnopvut | Yes |
| 14:25.42 | *** join/#asterisk-dev bof22 (~Thunderbi@ARennes-650-1-246-146.w2-14.abo.wanadoo.fr) |
| 14:26.03 | stefan27 | out of curiousity, if you offer audio+video is it legal to signal you support rtcp_mux for audio but not video in the SDP? |
| 14:27.39 | *** join/#asterisk-dev tm1000 (sid6728@gateway/web/irccloud.com/x-zaliphlccolpalax) |
| 14:28.18 | stefan27 | well mimicing that filter in chan_sip shouldn't be rocket science, but some asterisk-developer will do that for chan_sip eventually right? (there's so much overhead for me to get a gerrit client synced and working again :)) |
| 14:29.25 | putnopvut | From Asterisk's perspective, we only enable setting RTCP-MUX for all streams. It may be possible for a remote party to enable RTCP-MUX for one stream but not for another. Our understanding of remote support for RTCP-MUX is at the media description level, so that should still work properly. |
| 14:29.29 | stefan27 | I'm only a developer 10% of my time; i mostly administrate systems |
| 14:30.01 | stefan27 | But I would like to write more code and study more code! |
| 14:31.25 | stefan27 | Ah okay thanks |
| 14:37.09 | *** join/#asterisk-dev bof22 (~Thunderbi@ARennes-650-1-246-146.w2-14.abo.wanadoo.fr) |
| 14:37.39 | file | rmudgett: https://gerrit.asterisk.org/#/c/5545/ thoughts? |
| 14:38.12 | rmudgett | I haven't looked at it yet |
| 14:46.36 | stefan27 | putnopvut > rmudgett ! |
| 14:49.54 | scgm11_ | hi Im hitting a default session limit |
| 14:50.01 | scgm11_ | httpd_helper_thread: HTTP session count exceeded 100 sessions. |
| 14:50.10 | scgm11_ | where can I change that? |
| 14:50.17 | scgm11_ | http.conf dont see a value there |
| 14:50.35 | file | it's in http.conf |
| 14:50.38 | file | "sessionlimit" |
| 14:50.44 | file | under [general] |
| 14:51.46 | scgm11_ | thanks! |
| 15:56.33 | rmudgett | file: Concerning the To: header review. Is that something that would be needed by everyone all the time? |
| 15:56.54 | file | probably not |
| 15:57.09 | file | I don't think it'd hurt stuff.... |
| 15:58.28 | rmudgett | Was wondering since it hasn't been an issue for years |
| 16:11.21 | *** join/#asterisk-dev bof22 (~Thunderbi@ARennes-650-1-246-146.w2-14.abo.wanadoo.fr) |
| 17:54.23 | *** join/#asterisk-dev newtonr (~newtonr@173-21-147-197.client.mchsi.com) |
| 17:54.23 | *** mode/#asterisk-dev [+o newtonr] by ChanServ |
| 18:24.00 | *** join/#asterisk-dev pchero (~pchero@109.70.54.56) |
| 18:41.09 | *** join/#asterisk-dev jkroon (~jkroon@165.16.204.45) |
| 19:21.59 | *** join/#asterisk-dev jkroon (~jkroon@165.16.204.35) |
| 19:26.08 | *** join/#asterisk-dev malcolmd (malcolmd@pdpc/sponsor/digium/malcolmd) |
| 19:26.08 | *** mode/#asterisk-dev [+o malcolmd] by ChanServ |
| 19:31.55 | *** join/#asterisk-dev jkroon (~jkroon@165.16.204.39) |
| 20:49.06 | *** join/#asterisk-dev tzafrir (~tzafrir@bzq-179-40-170.cust.bezeqint.net) |
| 20:49.07 | *** mode/#asterisk-dev [+o tzafrir] by ChanServ |
| 21:10.31 | *** join/#asterisk-dev opticron (~opticron@75.76.59.35) |
| 21:10.32 | *** mode/#asterisk-dev [+o opticron] by ChanServ |
| 23:06.52 | *** part/#asterisk-dev kharwell (kharwell@nat/digium/x-zxpkhvokbasavfpu) |
| 23:26.56 | *** join/#asterisk-dev snuff-work (~snuff-wor@210.9.148.102) |
| 23:26.56 | *** mode/#asterisk-dev [+o snuff-work] by ChanServ |