| 00:19.12 | *** join/#asterisk-dev infobot (ibot@208.53.50.136) |
| 00:19.12 | *** 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:57.30 | X-Rob | so re https://issues.asterisk.org/jira/browse/ASTERISK-27987 - file does anything jump out at you that sleeps/blocks for 100msec if something is broken? I REALLY want to try to nail down the cause of this, because I hate not being able to give you 'this is how to cause it' test code |
| 06:27.26 | *** join/#asterisk-dev tsearle (~tsearle@37.19.10.33) |
| 06:27.26 | *** mode/#asterisk-dev [+o tsearle] by ChanServ |
| 06:51.26 | *** join/#asterisk-dev CELYA_ (~Thunderbi@2a01:e0a:d:1111:21c2:ffa5:3ca:d88d) |
| 06:53.21 | *** join/#asterisk-dev jkroon (~jkroon@165.16.204.167) |
| 08:21.42 | *** join/#asterisk-dev hehol (~hehol@gatekeeper.loca.net) |
| 12:07.44 | *** join/#asterisk-dev pchero (~pchero@176-23-78-252-cable.dk.customer.tdc.net) |
| 12:09.17 | *** join/#asterisk-dev jkroon_ (~jkroon@165.16.204.168) |
| 13:13.27 | *** join/#asterisk-dev hehol (~hehol@gatekeeper.loca.net) |
| 13:27.59 | *** join/#asterisk-dev viebig (c88fa9b5@gateway/web/freenode/ip.200.143.169.181) |
| 13:28.17 | viebig | Is it possible to playback and audio and run AMD at the same time ? |
| 13:41.58 | seanbright | not without modifying app_amd.c |
| 13:42.34 | seanbright | and if you're in the US or calling US numbers, please keep in mind that what you are trying to do will probably violate telemarketing and/or TCPA laws. |
| 14:20.30 | *** join/#asterisk-dev kharwell (kharwell@nat/digium/x-sulcvezgsnodkquv) |
| 14:20.30 | *** mode/#asterisk-dev [+o kharwell] by ChanServ |
| 14:46.56 | *** join/#asterisk-dev bford (uid283514@gateway/web/irccloud.com/x-qakergonfmglrkzp) |
| 14:46.56 | *** mode/#asterisk-dev [+o bford] by ChanServ |
| 15:14.13 | *** join/#asterisk-dev jkroon__ (~jkroon@165.16.204.165) |
| 15:30.19 | gtjoseph | bford: are you up on google chat? |
| 15:35.01 | *** join/#asterisk-dev rmudgett (rmudgett@nat/digium/x-xirmlhfeixmlyltt) |
| 15:35.01 | *** mode/#asterisk-dev [+o rmudgett] by ChanServ |
| 15:36.05 | bford | was talking to rmudgett, sorry :) |
| 16:34.25 | *** join/#asterisk-dev CELYA_ (~Thunderbi@2a01cb0583d31d00613a865ee46f4948.ipv6.abo.wanadoo.fr) |
| 16:46.35 | *** join/#asterisk-dev jkroon_ (~jkroon@165.16.204.174) |
| 16:51.07 | *** join/#asterisk-dev jkroon__ (~jkroon@165.16.204.164) |
| 18:07.40 | *** part/#asterisk-dev kharwell (kharwell@nat/digium/x-sulcvezgsnodkquv) |
| 18:09.11 | *** join/#asterisk-dev kharwell (kharwell@nat/digium/x-qvwbgayagnhxizei) |
| 18:09.11 | *** mode/#asterisk-dev [+o kharwell] by ChanServ |
| 18:53.58 | rmudgett | wonders if he should cherry-pick https://gerrit.asterisk.org/#/c/asterisk/+/9510/ to get things moving on it again. |
| 18:54.41 | gtjoseph | go for it |
| 19:01.09 | rmudgett | done :) |
| 19:07.56 | coreyfarrell | gtjoseph: about 9717 yes that is definitely needed for 16.0. I'm currently doing a more complete review of the .requires fields in built-in modules and realtime drivers, not sure if I should merge that to the ACL fix or do a separate patch. |
| 19:08.34 | gtjoseph | kk. if it's related and doesn't make the review too hard to review, then i'd say merge it. |
| 19:09.31 | coreyfarrell | what I've posted eliminates a potential security issue (being handled public since it's not in any release). the other stuff I'm working on will improve how the system handles realtime. so it'll be adding .requires and .enhances to a bunch of built-in and realtime modules. |
| 19:12.32 | rmudgett | gtjoseph: I wasn't sure if the compiled regex could be cached. The compiled struct may not be reentrant. |
| 19:13.16 | gtjoseph | i'm pretty sure we cache it other places but i guess you'd need to check |
| 19:15.53 | gtjoseph | rmudgett: iirc the compiled pattern buffer is immutable |
| 19:16.32 | file | yeah, I think so too |
| 20:11.41 | rmudgett | gtjoseph: Most places compile and destroy the regex_t in the same routine. Some places do cache it but most use it in one thread (AMI event filters, chan_ooh323). Sorcery may have multiple threads but I cannot be sure. Only ARI seems to use it in a global struct for its validators to validate dates. |
| 20:12.14 | gtjoseph | google says the compiled pattern is immutable |
| 20:13.13 | rmudgett | What did you use to search? |
| 20:13.29 | rmudgett | I didn't find anything explicit when I looked. |
| 20:14.22 | gtjoseph | regcomp thread safe |
| 20:18.43 | X-Rob | file: Can you point me at the bit of code that gets woken by timerfd? Is it timerfd_timer_ack? I'm trying to figure out where to put some debugging to nail down why timerfd isn't working properly |
| 20:19.06 | file | the code isn't common |
| 20:19.13 | X-Rob | Well crap |
| 20:19.38 | X-Rob | OK, this is more and more looking like something is breaking timerfd in the kernel |
| 20:19.57 | X-Rob | and when asterisk restarts it, it recreates it in an unbroken state |
| 20:20.07 | file | https://github.com/asterisk/asterisk/blob/master/bridges/bridge_softmix.c#L1787 |
| 20:20.16 | file | that waits on a timerfd file descriptor |
| 20:20.32 | X-Rob | so is that a select? |
| 20:20.33 | file | ast_waitfor_n_fd uses poll underneath |
| 20:20.36 | X-Rob | poll |
| 20:20.36 | X-Rob | ok |
| 20:20.43 | file | same function that is used for RTP sockets, pipes, etc |
| 20:21.52 | file | https://github.com/asterisk/asterisk/blob/master/main/timing.c#L252 |
| 20:21.55 | file | timing test just directly uses poll |
| 20:23.38 | X-Rob | Hmm. So if it's something with timerfd in the kernel, then if I ran a seperate process that ALSO used timerfd I should see glitches there, too. Because timing test did mess up. |
| 20:24.03 | X-Rob | At which point I have to throw my hands in the air and cry, because if this is a kernel issue, I'm way out of my depth. |
| 20:24.04 | file | probably? maybe? |
| 20:24.23 | file | I assume/hope timerfd isn't doing something process dependent |
| 20:26.24 | file | http://xmailserver.org/timerfd-test.c might be able to use that as a base and change the values to make it 20ms, but it's old and I dunno if it will even build |
| 20:26.43 | *** join/#asterisk-dev snuff-work (~snuff-wor@210.9.148.102) |
| 20:26.43 | *** mode/#asterisk-dev [+o snuff-work] by ChanServ |
| 20:28.10 | file | or run a second Asterisk with separate basic config that only allows it to start up so you can use timing test there |
| 20:28.40 | X-Rob | file: yeah I just found that, and it builds. |
| 20:28.51 | X-Rob | Oooh I like the second asterisk idea, that's even better. |
| 20:30.43 | X-Rob | But let's see what I can do with that test |
| 20:57.28 | X-Rob | ok, timerfd is rock solid on that machine outside of asterisk. |
| 20:59.04 | X-Rob | In a different process, I hacked on that timer-test to wake up every 20msec, and it was perfeect. But, while that was running, " has been 1036 milliseconds, and we got 48 timer ticks" |
| 21:03.05 | file | it doesn't appear to use the same interface we do |
| 21:03.29 | file | uses older stuff, don't know if that would impact stuff |
| 21:03.53 | X-Rob | So you feel a better test would be a seperate asterisk? |
| 21:04.23 | file | that would guarantee how we use it is tested |
| 21:12.55 | file | the other thing is somehow parts of Asterisk depriving resources such that only timerfd is impacted... but I don't know how that'd go, since RTP and such use the same polling/wakeup mechanism so I'd expect them to be impacted too |
| 21:18.49 | X-Rob | It's not timerfd. The other asterisk is perfect. |
| 21:19.15 | X-Rob | https://pastebin.freepbx.org/view/2899539e |
| 21:19.24 | X-Rob | while :; do echo Idle $(asterisk -C /tmp/asterisk/asterisk.conf -rx 'timing test' 2>&1 | grep we\ got); echo Active $(asterisk -rx 'timing test' 2>&1 | grep we\ got); sleep 1; done |
| 21:20.16 | file | then my only other idea is what I said above |
| 21:22.52 | X-Rob | I'll update what we've tried in the ticket |
| 21:35.24 | X-Rob | So yeah. AGI() causes ast_poll to slip. That's where we're at now. |
| 21:35.43 | gtjoseph | AGI when it's simply kickong off a process right? |
| 21:35.48 | X-Rob | Yep |
| 21:35.56 | X-Rob | I've got dialplan in that ticket |
| 21:36.05 | X-Rob | run it on a random machine, and then do 'timing test' |
| 21:36.08 | X-Rob | it will run slow |
| 21:42.11 | gtjoseph | X-Rob: so all i have to do is call an extension that has the following dialplan then run timing test? https://pastebin.com/YMEK0LBW |
| 21:43.11 | X-Rob | gtjoseph: no. You need to hammer AGIs to notice it when the machine is not in a broken state. |
| 21:43.43 | X-Rob | Use the dialplan in the description. That plays MoH and hammers AGI in the background |
| 21:43.56 | gtjoseph | so if i set up sipp to hammer asterisk with calls to the extension in my sample it will work. |
| 21:44.11 | X-Rob | Yeah, it should, but you don't need to playback. |
| 21:44.18 | X-Rob | you just want to AGI() and then hangup |
| 21:44.31 | gtjoseph | ok |
| 21:44.45 | X-Rob | You notice the problem when a playback is happening and an AGI happens on the system - WHEN the machine is broken. |
| 21:46.21 | X-Rob | So, this is how I am currently thinking of it. Something is causing ast_poll to delay slightly when AGI() is run in dialplan. There is something that happens on busy machines that breaches some bridgehead and that delay becomes significant and noticeable. |
| 21:47.34 | gtjoseph | well, i just tried it and couldn't do it. |
| 21:47.43 | gtjoseph | not sure what else we can do. |
| 21:47.49 | X-Rob | gtjoseph: OK, next question - is this a VM or Hardware? |
| 21:48.01 | X-Rob | Because - andI realise this is insane - I've only seen this on hardware, not in VMs |
| 21:48.05 | gtjoseph | tested on my desktop |
| 21:48.34 | gtjoseph | that would suggest a hardware issue. |
| 21:48.52 | gtjoseph | do you have HPET enabled? |
| 21:48.56 | X-Rob | gtjoseph: Can you try it with my dialplan? |
| 21:49.00 | gtjoseph | i just did |
| 21:49.08 | X-Rob | And you didn't have any slippage at all? |
| 21:49.14 | gtjoseph | nope |
| 21:49.41 | X-Rob | I've got a random HP blade that I was testing this ojn |
| 21:49.47 | X-Rob | that paste was from that |
| 21:49.51 | *** part/#asterisk-dev kharwell (kharwell@nat/digium/x-qvwbgayagnhxizei) |
| 21:50.04 | X-Rob | Oh hang on, no it wasn't, that was from a blade elsewhere. |
| 21:50.10 | X-Rob | Anywya, let me try this again |
| 21:51.21 | X-Rob | gtjoseph: Just turning that blade back on. They take so long to boot. Let me try to replicate this again. |
| 21:51.22 | gtjoseph | i didn't read all the comments on the issue but i gather you cannot reproduce this on any platform other than your main pbx, correct? |
| 21:52.21 | X-Rob | gtjoseph: that is incorrect. This is happening on 3 machines that I know of, plus various others have reported it over the years, but because this is so insanely hard to replicate AND because it only happens after some magic trigger, it seems to have been treated as 'one of those things' |
| 21:52.56 | X-Rob | but I now have access to a new machine that is getting into this state every 24 hours or so - but they're doing 35k calls in that 24 hour period. It's a busy machine. |
| 21:53.09 | X-Rob | sangoma pbx does it every week or so |
| 21:53.14 | gtjoseph | tdm or analog cards? |
| 21:53.21 | X-Rob | no hardware cards. |
| 21:53.29 | gtjoseph | what hardware specs? |
| 21:53.38 | gtjoseph | what OS and kernel version? |
| 21:53.55 | X-Rob | client machine new 32 core xeon, Intel(R) Xeon(R) CPU E5-2620 v4 @ 2.10GHz |
| 21:54.15 | X-Rob | sangoma pbx older blade Intel(R) Xeon(R) CPU E5640 @ 2.67GHz |
| 21:54.33 | X-Rob | my test machine ancient dual quad core xeon, and it's still booting |
| 21:54.38 | X-Rob | all RHEL7 kernels |
| 21:55.00 | gtjoseph | All SMP though. hmmm |
| 21:55.21 | gtjoseph | if you can reproduce it on a test machine, turn 1 socket off |
| 21:55.27 | gtjoseph | and see what happens |
| 21:55.45 | gtjoseph | and check the bios for HPET |
| 21:56.03 | gtjoseph | and look at dmesg for TSC |
| 21:56.33 | gtjoseph | then find a linux kernel expert :) |
| 21:56.37 | X-Rob | There's nothing in dmesg, that's the first thing I checked |
| 21:56.48 | gtjoseph | not just errors |
| 21:56.53 | gtjoseph | loo for the TSC |
| 21:57.01 | X-Rob | but this is NOT a kernel issue, we verified that by running two asterisk's at the same time. The one that wasn't broken was perfect |
| 21:57.27 | gtjoseph | so what was the difference between them? |
| 21:57.42 | file | verified is a strong word |
| 21:57.43 | X-Rob | One had been running for 24 hours and had 25k calls through it |
| 21:58.06 | gtjoseph | and the other? |
| 21:58.08 | X-Rob | and when that one hit AGI() in dialplan, ast_poll froze |
| 21:58.18 | X-Rob | The other was just started. |
| 21:58.28 | gtjoseph | so they were both configured exactly the same? |
| 21:58.31 | X-Rob | If I restart the running one, the problem goes away |
| 21:59.10 | X-Rob | No, one was just asterisk with no configuration. This was to check if timerfd was playing up, inside the kernel. |
| 21:59.27 | gtjoseph | well, that doesn't relly mean anything then |
| 21:59.33 | X-Rob | It means it's not timerfd |
| 21:59.46 | gtjoseph | it only meand that it wasn't THAT PROCESS. |
| 22:00.33 | gtjoseph | they might not have been running on the same physical CPU |
| 22:02.58 | X-Rob | OK, good point. Let me see what I can do about duplicating this timing issue here. |
| 22:03.06 | gtjoseph | cool |
| 22:03.23 | gtjoseph | i've been at my desk for about 12 hours anyway. |
| 22:03.27 | X-Rob | Heh |
| 22:03.29 | gtjoseph | time to leave |
| 22:03.36 | X-Rob | I was up until 11pm, and was up at 5 |
| 22:03.44 | X-Rob | thanks for your time, gtjoseph |
| 22:03.53 | gtjoseph | yep. hope you get it sorted |
| 22:03.54 | X-Rob | Really appreciated. Sorry this is such a horrible one |
| 22:04.28 | X-Rob | Happened straight away for me |
| 22:04.37 | X-Rob | https://www.irccloud.com/pastebin/UV44JZj9/slip.txt |
| 22:05.04 | X-Rob | https://www.irccloud.com/pastebin/4VlWLBPA/dialplan.txt |
| 22:05.35 | file | 1001 isn't the end of the world, dropping timer ticks is though |
| 22:06.00 | X-Rob | Well, that's the symptom though - ast_poll isn't returning quickly enough. |
| 22:06.12 | X-Rob | well |
| 22:06.14 | X-Rob | that's what I think |
| 22:06.20 | X-Rob | I'm probably wrong |
| 22:06.23 | file | to be pedantic, the poll() system call |
| 22:06.32 | X-Rob | this is like my 5th idea so far |
| 22:07.42 | X-Rob | file: Mmmm there was a bunch of stuff around that code though - #define ast_poll(a, b, c) ast_internal_poll(a, b, c) |
| 22:08.30 | file | 'tis poll, it's wrapped for platforms that don't support it as-is |
| 22:08.33 | file | which Linux is not one of them |
| 22:08.44 | X-Rob | ah, ok |
| 22:09.18 | X-Rob | #ifndef AST_POLL_COMPAT |
| 22:09.19 | X-Rob | #include <poll.h> |
| 22:09.19 | X-Rob | #define ast_poll(a, b, c) poll(a, b, c) |
| 22:09.19 | X-Rob | #else /* AST_POLL_COMPAT */ |
| 22:09.29 | X-Rob | So... that's where we're at? |
| 22:09.57 | file | 'tis the poll system call with timerfd as the sole file descriptor in the case of ConfBridge and timing test |
| 22:10.08 | X-Rob | Yeah |
| 22:11.11 | X-Rob | I'm just going to rebuild asterisk to make sure I'm not doing something dumb to break that |
| 22:11.40 | file | and in the case of AGI, the execv system call |
| 22:11.57 | file | and a fork. |
| 22:12.27 | file | it's all very much at the edge of the kernel |
| 22:12.33 | X-Rob | I can't duplicate the issue on my test machine any more. |
| 22:12.39 | X-Rob | it's 1000/50 perfectly, all the time now |
| 22:13.00 | X-Rob | Sigh |
| 22:15.22 | X-Rob | So I changed my test loop from just AG() to a Dial(SIP/111@localhost) so it goes through all the freepbx dialplan |
| 22:15.34 | X-Rob | and I got a 1001 ms |
| 22:16.09 | file | it's not realtime, so you aren't absolutely guaranteed, the system may still schedule things such that it doesn't wake up precisely on time |
| 22:16.10 | X-Rob | file: My original thought, honestly, is that it's something to do with unixodbc. |
| 22:16.22 | X-Rob | I really would love it to be that |
| 22:18.00 | file | I don't know how it could be, unless it was eating resources such that the kernel delayed the specific timerfds in the process so they woke up later |
| 22:19.05 | file | I honestly don't know what impact forking and execing the AGIs have on the parent process over all to that level |
| 22:20.44 | X-Rob | Agree. I'm now thinking maybe FD allocation in execve is blocking in the kernel or something |
| 22:21.12 | X-Rob | I wonder what would happen if I 'lose' a file handle in the AGI. |
| 22:21.24 | file | some quick Googling shows that as the process grows in memory usage forking may take longer, if that's still true on your kernel and what impact that has on timerfd also dunno |
| 22:26.54 | X-Rob | https://www.irccloud.com/pastebin/YOAYw8DW/badcode.sh |
| 22:27.15 | X-Rob | So that should leak a filehandle in an AGI. |
| 22:27.18 | X-Rob | Let's see what happens |
| 22:29.02 | X-Rob | Hmm. Nope. |
| 22:44.02 | X-Rob | HOLY CRAP MY TEST MACHINE IS DOING IT |
| 22:44.07 | X-Rob | does the happy dance |
| 22:44.52 | X-Rob | While I was fiddling with that shellscript, whatever happened happened, and my test machine is now broken |
| 22:47.58 | X-Rob | But timing test is perfect. |
| 23:09.58 | file | X-Rob: you really need to be explicit in your comments :P |
| 23:10.32 | X-Rob | I feel like I'm *so close* to figuring out what's causing it |
| 23:10.41 | X-Rob | I've never been able to duplicate this before |
| 23:11.36 | X-Rob | Also you seriously need to upgrade your jira, it's so out of date |
| 23:11.49 | X-Rob | You should use my containers, it makes it so much easier |
| 23:12.05 | file | it's in the plans, but we can't just drop everything in the known universe to upgrade JIRA :P |
| 23:13.50 | X-Rob | https://hub.docker.com/r/atlassianunofficial/jira/ |
| 23:14.05 | file | it's not that easy. |
| 23:14.19 | X-Rob | I know. It took me like a week to migrate all of our stuff |
| 23:14.31 | file | that's part of it |
| 23:14.40 | file | we are also waiting on equipment at a new datacenter |
| 23:14.48 | file | and we have custom mods we have to remove and replicate some in a different fashion |
| 23:14.59 | file | we also have to do upgrades of various other things |
| 23:15.02 | X-Rob | Heaps of fun |
| 23:15.08 | file | and we also have our regular stuff to do |
| 23:15.15 | file | :P |
| 23:15.35 | file | so, we'll get there hopefully by the end of this year |
| 23:15.51 | file | but it's not a week thing it's more of a month thing |
| 23:16.55 | X-Rob | OK, so a restart of asterisk fixed it. I did a bunch of stuff that was screwing around with dropping filehandles in AGIs and it's not broken. The only thing different is when it broke last time was after I'd done 20k or so Dial(SIP/localhost) calls. |
| 23:17.04 | X-Rob | So.. I Guess do that again. Sigh |
| 23:19.06 | X-Rob | subm:cel_aggregation_topic-00000006 237954 119228 135556 2700 3000 |
| 23:19.08 | X-Rob | Heh |
| 23:21.00 | X-Rob | https://www.irccloud.com/pastebin/0YIcQ1z8/lostcalls |
| 23:21.28 | X-Rob | The phone is hung up, both sip and pjsip, but asterisk still thinks there's calls there. |
| 23:21.39 | X-Rob | I didn't check that last time. Sigh. |
| 23:24.05 | X-Rob | OK, it's the Dial() that breaks it. |
| 23:46.43 | *** join/#asterisk-dev CELYA_1 (~Thunderbi@LFbn-1-5196-144.w90-105.abo.wanadoo.fr) |