| 01:36.15 | *** join/#asterisk-dev _longines (~longines@static.183.80.201.138.clients.your-server.de) |
| 02:11.43 | *** join/#asterisk-dev leedm777 (~textual@50-81-28-152.client.mchsi.com) |
| 02:47.29 | *** join/#asterisk-dev leedm777 (~textual@50-81-28-152.client.mchsi.com) |
| 03:52.17 | *** join/#asterisk-dev luckman212 (~luckman21@unaffiliated/luckman212) |
| 04:25.10 | *** join/#asterisk-dev jkroon (~jkroon@uls-154-73-32-13.wall.uls.co.za) |
| 05:08.03 | *** join/#asterisk-dev bof22 (~Thunderbi@185.13.183.107) |
| 05:22.17 | *** join/#asterisk-dev luckman212 (~luckman21@unaffiliated/luckman212) |
| 06:25.26 | *** join/#asterisk-dev pchero (~pchero@109.70.54.56) |
| 06:48.48 | *** join/#asterisk-dev CELYA_ (~Thunderbi@LStLambert-657-1-90-73.w80-13.abo.wanadoo.fr) |
| 07:06.41 | *** join/#asterisk-dev klow (~textual@c-98-247-49-57.hsd1.wa.comcast.net) |
| 07:21.23 | *** join/#asterisk-dev tzafrir (~tzafrir@local.xorcom.com) |
| 07:21.23 | *** mode/#asterisk-dev [+o tzafrir] by ChanServ |
| 07:26.51 | *** join/#asterisk-dev opticron (~opticron@75.76.59.35) |
| 07:26.51 | *** mode/#asterisk-dev [+o opticron] by ChanServ |
| 07:36.34 | *** join/#asterisk-dev pchero_work (~pchero@109.70.54.56) |
| 07:42.15 | *** join/#asterisk-dev jkroon (~jkroon@uls-154-73-35-201.wall.uls.co.za) |
| 07:49.56 | *** join/#asterisk-dev tirej (~tirej_@95.9.123.3) |
| 08:05.25 | *** join/#asterisk-dev CELYA_1 (~Thunderbi@lcy44-2-88-161-121-174.fbx.proxad.net) |
| 08:20.45 | *** join/#asterisk-dev luckman212 (~luckman21@unaffiliated/luckman212) |
| 09:34.50 | *** join/#asterisk-dev skrusty (~skrusty@168.63.14.171) |
| 11:04.03 | coreyfarrell | gerrit sign-in is not working (just freezes) |
| 11:08.02 | file | fun |
| 11:09.07 | file | that's over in Crowd, hrmph |
| 11:29.11 | *** join/#asterisk-dev lnxlsck (~bruno@av3-84-90-162-98.netvisao.pt) |
| 11:32.07 | coreyfarrell | also strange it looks like jenkins is sending messages to asterisk-code-review but gerrit isn't.. I got messages about wdoekes reviews passing tests but no message for him actually posting the updated code. |
| 11:54.15 | file | I lack access to the server Crowd is on, so it'll have to wait until someone in HSV wakes up/gets in |
| 12:02.14 | coreyfarrell | np thanks for trying |
| 12:03.53 | file | Rusty is transitioning more into handling that stuff, so hopefully he has access so he can take a gander and get some experience in ye ol' Crowd land |
| 12:36.01 | file | la la la |
| 12:37.57 | file | coreyfarrell, fixed |
| 12:38.10 | coreyfarrell | oh, I was just about to try posting a +1 from command-line |
| 12:43.53 | *** join/#asterisk-dev leedm777 (textual@nat/digium/x-lpsvhogstvbmvqeb) |
| 13:00.50 | *** join/#asterisk-dev CELYA_ (~Thunderbi@80.12.34.86) |
| 13:12.08 | coreyfarrell | gtjoseph: I'm assuming "3522376 logger: Support JSON logging with Verbose messages" caused it, unless you've already started I'm going to try a build with that reverted. |
| 13:12.31 | gtjoseph | go for it! |
| 13:30.36 | coreyfarrell | gtjoseph: so interesting thing, configs/samples/logger.conf.sample does not include 'verbose' in the console channel. appears it is required since 3522376. |
| 13:30.56 | gtjoseph | that's weird |
| 13:31.07 | gtjoseph | the required bit that is |
| 13:36.48 | coreyfarrell | configs/basic-pbx/logger.conf has 'console = verbose,notice,warning,error'. I'm tempted to just update the configs/samples and put a note in UPGRADE.txt. |
| 13:41.24 | gtjoseph | but it doesn't work even with verbose in there |
| 13:43.03 | coreyfarrell | gtjoseph: works for me, you still need 'asterisk -rv' or 'asterisk -cv' to enable verbose for the specific console.. |
| 13:43.33 | gtjoseph | you mean in the current codebase? |
| 13:43.57 | gtjoseph | or after your revert? |
| 13:44.08 | coreyfarrell | current 14 without the revert |
| 13:45.10 | coreyfarrell | all I did was 'console => notice,warning,error,verbose' in my logger.conf and it works. |
| 13:45.21 | gtjoseph | i already had that |
| 13:46.09 | gtjoseph | do you start asterisk with a -v or with verbose>0 in asterisk.conf? |
| 13:46.32 | gtjoseph | i do neither and you could always set it later in the console |
| 13:46.36 | gtjoseph | can't now |
| 13:47.03 | coreyfarrell | you mean 'core set verbose 1' ? |
| 13:47.15 | gtjoseph | yeah |
| 13:47.40 | gtjoseph | wait...maybe... |
| 13:48.06 | coreyfarrell | trying that.. I've verified that 'asterisk -cv' works, and 'asterisk -rv' works even if you started asterisk without -v. |
| 13:48.08 | gtjoseph | yeah, damn. |
| 13:48.41 | coreyfarrell | core set verbose 1 worked for me too after starting with 'asterisk -c' |
| 13:48.51 | gtjoseph | on 3 of my pbxes I don't have verbose in console and it worked on 13 so when I upgraded I didn't check logger.conf |
| 13:49.27 | gtjoseph | you're right, it was a change that should have been documented. |
| 13:50.17 | *** join/#asterisk-dev cresl1n (Adium@asterisk/libpri-and-libss7-expert/Cresl1n) |
| 13:50.17 | *** mode/#asterisk-dev [+o cresl1n] by ChanServ |
| 13:50.23 | coreyfarrell | yup so the change is acceptable once documented.. ? |
| 13:51.15 | gtjoseph | good question. |
| 13:51.36 | gtjoseph | asking the boss... cresl1n? |
| 13:51.45 | file | he just joined, you'll have to fill him in :P |
| 13:51.55 | file | I'm a bit iffy |
| 13:52.24 | cresl1n | blinks |
| 13:52.52 | gtjoseph | the issue is that there a console logging change 13->14 that wasn't documented |
| 13:53.35 | gtjoseph | on 13 even if you didn't specify "verbose" in the console logger channel you could still get verbose messages on the console with "core set verbose n" |
| 13:53.59 | gtjoseph | in 14, you MUST have "verbose" in the console logger channel. |
| 13:54.07 | gtjoseph | or you get nothing |
| 13:54.28 | cresl1n | Ok |
| 13:55.16 | gtjoseph | so the question is for 14... just fix the docs or make specifying verbose not required again? |
| 13:55.36 | gtjoseph | given we just released 14.0.0-rc1 |
| 13:56.06 | gtjoseph | https://issues.asterisk.org/jira/browse/ASTERISK-26391 |
| 13:56.52 | cresl1n | Yay for progress |
| 13:56.57 | cresl1n | :-) |
| 13:57.04 | cresl1n | It will probably surprise other people |
| 13:57.31 | cresl1n | but on the other hand, if you understand the way the logger outputs work, it makes sense |
| 13:57.32 | coreyfarrell | part of the problem is that samples/configs/logger.conf does not include verbose for console. |
| 13:57.39 | gtjoseph | exactly |
| 13:57.54 | cresl1n | Yeah, so for people migrating from old configs, this will be an issue |
| 13:58.09 | cresl1n | Why/When did we change it? |
| 13:58.24 | coreyfarrell | 3522376 logger: Support JSON logging with Verbose messages" caused it |
| 13:58.33 | file | year+ ago |
| 13:59.36 | cresl1n | Was it an intended change? |
| 14:01.14 | cresl1n | or was it an unintended consequence? |
| 14:02.22 | *** join/#asterisk-dev kharwell (kharwell@nat/digium/x-cyqvdtcwdwpntqif) |
| 14:02.22 | cresl1n | hears crickets |
| 14:02.42 | file | knows nothing, points at coreyfarrell and gtjoseph |
| 14:02.54 | gtjoseph | i know nothing either |
| 14:03.10 | coreyfarrell | from the commit msg it looks like making verbose log messages more like other log messages was intended, obviously the issue with existing configs wasn't realized. |
| 14:03.18 | gtjoseph | and am cherry-picking something else ATM |
| 14:03.54 | file | coreyfarrell, from my quick perusal I agree |
| 14:05.25 | file | I'm still iffy |
| 14:05.34 | cresl1n | about remediation plans? |
| 14:05.45 | file | oui |
| 14:05.55 | cresl1n | that's my problem too |
| 14:06.18 | gtjoseph | since it's making the behavior more consistent and it doesn't affect call processing i'd say just change the docs |
| 14:06.35 | gtjoseph | and configs |
| 14:06.44 | file | it may not affect call processing but it's something that is very evident if it's not right |
| 14:06.57 | cresl1n | It'd be surprising to me I think |
| 14:06.57 | file | when 14 starts getting used we'll likely see more cases |
| 14:07.27 | file | that's why I'm iffy |
| 14:07.28 | gtjoseph | it was to me as well. i noticed it last night. but we have to do a patch either way |
| 14:07.43 | file | I'm leaning towards fixing it so behavior remains consistent, even without config change |
| 14:07.52 | file | preferably soonish |
| 14:08.04 | gtjoseph | consistent with 13? |
| 14:08.08 | file | oui |
| 14:08.29 | cresl1n | I wouldn't complain if you did fix it |
| 14:08.56 | gtjoseph | works for me. rc2 then? |
| 14:09.00 | cresl1n | I would be very frustrated updating to 14 and trying to figure out why I wasn't getting the messages I think I should be getting |
| 14:09.21 | cresl1n | But I understand gtjoseph's point too |
| 14:09.44 | cresl1n | verbose has always been special in a sense |
| 14:09.54 | file | sure, but users don't care about that :P |
| 14:10.00 | gtjoseph | i'm all for making it work like 13 if we can get it done within our time constraints |
| 14:10.13 | cresl1n | ok, let's try to do it |
| 14:10.23 | cresl1n | coreyfarrell: what say you? |
| 14:10.43 | file | Malcolm agrees btw :P |
| 14:10.48 | cresl1n | cool |
| 14:11.21 | coreyfarrell | I think when we parse logger.conf we just pretend that console contained verbose.. |
| 14:11.29 | cresl1n | sounds good |
| 14:13.06 | stefan27 | asterisk 14 will include chan_sip too? |
| 14:13.30 | file | yes. |
| 14:14.36 | stefan27 | next time we do major upgrade we'll probably consider switching to pjsip anyways... but that's years away. Good luck with your 14 release! |
| 14:15.04 | gtjoseph | coreyfarrell: file: I just cherry-picked tzafrir's sd_notify patch to 13 and 14 and tested both if you want to take a quick look since you both +1'd the master version. |
| 14:15.11 | file | kk |
| 14:15.18 | file | stefan27, merci! |
| 14:16.22 | tzafrir | gtjoseph, thank |
| 14:16.47 | gtjoseph | no problem! |
| 14:17.30 | gtjoseph | at this point i'll do anything to put off working on my chan_sip issue. :) |
| 14:17.54 | file | eyes gtjoseph |
| 14:18.22 | gtjoseph | yeah, yeah. back to the salt mine that is chan_sip |
| 14:18.35 | file | we've all done our time |
| 14:18.52 | file | and promptly blocked out the memories |
| 14:44.42 | *** join/#asterisk-dev newtonr (RustyNewto@nat/digium/x-frzfuurfznyirryu) |
| 14:44.42 | *** mode/#asterisk-dev [+o newtonr] by ChanServ |
| 14:52.54 | *** join/#asterisk-dev rmudgett (rmudgett@nat/digium/x-pvuoraldbhstbclh) |
| 15:10.48 | coreyfarrell | gtjoseph: looks like init_logger was moved to run too early as well. weird thing running init_logger then calling ast_log before ast_makesocket causes the message to be repeated many times. |
| 15:11.59 | gtjoseph | hmmm |
| 15:12.12 | gtjoseph | we're all in a meeting for a bit. |
| 15:12.30 | *** join/#asterisk-dev CELYA_ (~Thunderbi@LStLambert-657-1-90-73.w80-13.abo.wanadoo.fr) |
| 15:13.34 | coreyfarrell | don't worry I'm fixing that too.. just thought you'd find it interesting. |
| 15:44.49 | *** join/#asterisk-dev jkroon (~jkroon@uls-154-73-32-13.wall.uls.co.za) |
| 15:53.16 | cresl1n | Did something between 13 and 11 change where there aren't fax status events sent via AMI anymore? |
| 15:54.59 | file | no? the option is still there |
| 15:57.01 | cresl1n | Hrm... |
| 15:59.50 | file | it was changed to use stasis but nothing else stands out, unless a call to raise it got lost in the conversion |
| 16:00.45 | cresl1n | interesting |
| 16:30.43 | file | gtjoseph, chan_sip? |
| 16:30.53 | gtjoseph | yes.... |
| 16:31.21 | file | you had a query? |
| 16:31.39 | gtjoseph | when sip_destroy_peer is called, we call destroy_mailbox, which calls stasis_unsubscribe_and_join |
| 16:32.23 | gtjoseph | join waits for final_message_processed |
| 16:32.27 | file | yup |
| 16:32.30 | gtjoseph | which nothing sets |
| 16:32.39 | gtjoseph | so the join waits forever |
| 16:32.58 | gtjoseph | so why call join in the first place? |
| 16:33.07 | gtjoseph | why not just unsubscribe and go |
| 16:33.53 | gtjoseph | are we thinking that when stasis notifies "someone" else about the unsubscription that that "someone" will try and use the peer before it's destroyed? |
| 16:34.17 | file | I believe it's to ensure that any in-flight messages are processed before returning |
| 16:34.36 | gtjoseph | whyt do we care if we're destroying the sip_mailbox and peer? |
| 16:34.50 | gtjoseph | the peer's destructor is already in progress |
| 16:34.53 | gtjoseph | actually |
| 16:35.09 | file | a scenario is present in stasis.h for it actually |
| 16:35.24 | coreyfarrell | also to prevent any callbacks from running late if we're unloading chan_sip |
| 16:35.29 | file | yeah |
| 16:36.24 | gtjoseph | hmmmmm |
| 16:37.32 | gtjoseph | doesn't really answer my question about why destroying a peer needs to do the join. |
| 16:37.48 | gtjoseph | there can be no references top the peer at that point |
| 16:38.20 | file | if you unload and the peer is destroyed if you don't join there is a chance that the callback will occur into the module after it is unloaded, that's the scenario described |
| 16:39.46 | file | in this issue you are destroying it in the thread which is handling stasis messages I believe, so in that case yeah you can't |
| 16:39.58 | gtjoseph | what if there's no final message? |
| 16:40.26 | gtjoseph | which is the case here. |
| 16:40.37 | file | in a normal situation, there is |
| 16:41.07 | gtjoseph | well chan_sip is anything but normal. :) |
| 16:42.01 | rmudgett | It is normal for chan_sip |
| 16:42.36 | file | if the unsubscribe_and_join is in the thread that is handling stasis messages, then you can't do that and it will deadlock and never get a final message |
| 16:44.03 | gtjoseph | if I unsubscribe_and_join and there are no other messages pending, what should happen? |
| 16:44.53 | rmudgett | There would always be one message pending: the final message |
| 16:45.00 | file | you can't reliably try to support that scenario within the stasis message thread |
| 16:45.04 | gtjoseph | the unsubscribe itself will cause new messages to be generated correct? |
| 16:45.13 | file | yes. |
| 16:45.30 | gtjoseph | what's "the final message" |
| 16:45.58 | file | it's the message generated by the unsubscribe that join waits on, when it's received you know it's at the end of the queue |
| 16:46.21 | rmudgett | There is a final message sent to the subscriber to let the subscriber know that it will not get any more messages. |
| 16:46.22 | gtjoseph | the problem is that stasis_subscription_final_message ignores unsubscribes. |
| 16:46.43 | gtjoseph | oh, not the Unsubscribe message itself then |
| 17:08.52 | *** join/#asterisk-dev CELYA_ (~Thunderbi@2a01cb0583d31d0095a159996f8be8e9.ipv6.abo.wanadoo.fr) |
| 17:15.35 | *** join/#asterisk-dev tzafrir (~tzafrir@bzq-218-28-58.cablep.bezeqint.net) |
| 17:15.35 | *** mode/#asterisk-dev [+o tzafrir] by ChanServ |
| 17:52.10 | *** join/#asterisk-dev klow (~textual@96-81-150-137-static.hfc.comcastbusiness.net) |
| 19:11.30 | *** join/#asterisk-dev luckman212 (~luckman21@unaffiliated/luckman212) |
| 19:14.36 | *** join/#asterisk-dev leedm777 (textual@nat/digium/x-kzlkeqoaltnstkhv) |
| 19:59.44 | coreyfarrell | gtjoseph: any reason you made ast_pbx_uuid_get unavailable to LOW_MEMORY? |
| 20:00.02 | gtjoseph | yes, i was a knucklehead. |
| 20:00.26 | gtjoseph | that LOW_MEMORY block is so big I didn't realize that the cli command was in it |
| 20:00.42 | gtjoseph | we have an internal issue to fix it but feel free |
| 20:00.45 | gtjoseph | :) |
| 20:01.38 | coreyfarrell | yeah I'll post a review quick. |
| 20:02.45 | gtjoseph | i think it lust needs to be moved up before the ifdef |
| 20:02.54 | coreyfarrell | yup.. |
| 20:05.36 | coreyfarrell | gtjoseph: so there isn't a public jira ticket yet? |
| 20:05.50 | gtjoseph | checking |
| 20:05.55 | gtjoseph | i think there is |
| 20:06.03 | coreyfarrell | oh found it nm |
| 20:06.34 | gtjoseph | 26273? |
| 20:07.37 | gtjoseph | back to stasis and chan_sip. in subscription_invoke, wouldn't checking for final_message_processed before calling the callback have fixed the issue with disappearing objects for messages after unsubscribe? |
| 20:08.10 | gtjoseph | or maybe not |
| 20:10.08 | *** join/#asterisk-dev luckman212 (~luckman21@unaffiliated/luckman212) |
| 20:19.30 | coreyfarrell | for ASTERISK-26273 (pbx uuid) and ASTERISK-26391 (console verbose) what do I do about 14.0.0? |
| 20:19.41 | file | cherry pick to 14.0 |
| 20:22.37 | coreyfarrell | gerrit is weird about what it lists as conflicts lately |
| 20:26.18 | rmudgett | gtjoseph: I seem to be missing something when trying to use bundled pjsip. |
| 20:26.30 | gtjoseph | and what would that be? |
| 20:26.35 | rmudgett | I've uninstalled pjlib |
| 20:27.00 | rmudgett | confiured --with-bundled-pjproject |
| 20:27.38 | rmudgett | but asterisk wont load because it is trying to load libpj.so.2 |
| 20:28.08 | rmudgett | libasteriskpj.so is installed in /usr/lib |
| 20:28.32 | gtjoseph | ldconfig |
| 20:28.46 | rmudgett | ldconfig no longer has any pj libs in it |
| 20:29.23 | gtjoseph | ldd libasteriskpj.so |
| 20:29.57 | gtjoseph | 32 or 64? what distro? |
| 20:30.26 | rmudgett | kubuntu 10.4 32 bit |
| 20:30.37 | rmudgett | ldd showing libpj.so.2 as not found |
| 20:30.39 | gtjoseph | oh yeah. dark ages. |
| 20:30.55 | gtjoseph | then you have a bad libasteriskpj.so |
| 20:31.01 | rmudgett | I won't be in the dark ages too much longer |
| 20:31.21 | rmudgett | Hmm. And I just compiled it. |
| 20:31.29 | gtjoseph | is th e.so in /usr/lib the same one as in main/ |
| 20:32.18 | rmudgett | It better be since I deleted it. and main/ was rebuilt after a distclean |
| 20:32.35 | gtjoseph | uh huh. |
| 20:34.05 | rmudgett | file sizes are the same and the timestamps are 3 mins apart |
| 20:34.49 | gtjoseph | hash or it didn't happen :) |
| 20:35.37 | gtjoseph | have a look at makeopts and config.log and make sure it actually discovered the bundled version. |
| 20:35.59 | gtjoseph | sounds like it built for non-bundled |
| 20:36.16 | rmudgett | That's what it seems like |
| 20:36.31 | rmudgett | What program hashes files? |
| 20:36.47 | gtjoseph | md5sum shaNsum |
| 20:37.14 | gtjoseph | look at makeopts first... PJPROJECT_* |
| 20:37.52 | rmudgett | md5sums are the same |
| 20:38.30 | gtjoseph | you sure you didn't typo --with-pjproject-bundled |
| 20:38.44 | rmudgett | PJPROJECT_BUNDLE=yes |
| 20:39.48 | gtjoseph | 'make thirdparty" |
| 20:40.02 | gtjoseph | third-party |
| 20:41.48 | rmudgett | make third-party didn't output anything |
| 20:41.50 | gtjoseph | or (cd third-party/pjproject ; make clean ; make NOISY_BUILD=yes" |
| 20:46.58 | rmudgett | libsrtp.so wants libpj.so ??? |
| 20:47.10 | gtjoseph | eh? |
| 20:47.17 | gtjoseph | what libsrtp.so? |
| 20:47.48 | gtjoseph | did you accidentally overwrite the distro's version with one that pjproject may have built on it's own |
| 20:47.56 | rmudgett | The last thing the make was trying to do got a warning message that libsrtp.so wanted libpj.so |
| 20:48.28 | gtjoseph | find libsrtp.so |
| 20:48.50 | gtjoseph | then delete it and reinstall your libsrtp-dev package |
| 20:49.14 | gtjoseph | if you build pjproject from their source, it can build a libsrtp of it's own and install it. |
| 20:49.17 | rmudgett | Yeah. ldd on my libsrtp.so wanted libpj.so |
| 20:50.54 | gtjoseph | that's odd though. which make complained about libsrtp? |
| 20:51.39 | rmudgett | make third-party |
| 20:51.54 | rmudgett | w/ noisy build |
| 20:52.21 | gtjoseph | ah, yeah ok. |
| 20:53.02 | rmudgett | crap. I think the kubunto 10.4 package servers are removed |
| 20:53.24 | gtjoseph | :) |
| 20:54.57 | gtjoseph | any other luddites out there that can give it to you? |
| 20:55.24 | gtjoseph | and when you're done, you owe me 25 minutes of dedicated time on chan_sip and stasis. |
| 20:59.22 | rmudgett | Say is libsrtp supposed to be built as a static or dynamic library? |
| 20:59.30 | rmudgett | from packages? |
| 20:59.31 | gtjoseph | dynamic |
| 21:00.21 | rmudgett | It only pulled down a .a library not a .so library |
| 21:00.37 | rmudgett | Might explain the libpj.so dependency |
| 21:01.17 | gtjoseph | is there a -static or -shared version of the packages? |
| 21:01.34 | gtjoseph | or did you pull just libsrtp-dev or did you libsrtp as well? |
| 21:01.46 | rmudgett | just libsrtp-dev |
| 21:01.57 | gtjoseph | that's probably why |
| 21:01.58 | rmudgett | It was the only one it found |
| 21:02.41 | gtjoseph | was there a versioned .so and there just needs to be a link created? |
| 21:13.31 | rmudgett | gtjoseph: Does your system have a libsrtp.a and .so? |
| 21:14.04 | gtjoseph | $ dir /usr/lib64/libsrtp* |
| 21:14.04 | gtjoseph | lrwxrwxrwx. 1 root root 16 Mar 2 2016 /usr/lib64/libsrtp.so -> libsrtp.so.1.0.0 |
| 21:14.04 | gtjoseph | lrwxrwxrwx. 1 root root 16 Mar 2 2016 /usr/lib64/libsrtp.so.1 -> libsrtp.so.1.0.0 |
| 21:14.04 | gtjoseph | -rwxr-xr-x. 1 root root 100896 Mar 2 2016 /usr/lib64/libsrtp.so.1.0.0 |
| 21:14.08 | gtjoseph | nope |
| 21:16.46 | rmudgett | The earlier problem I had with getting the package was because of a password dialog box hidden under other windows. |
| 21:18.08 | gtjoseph | windows? i thought you were on an 80x24 VT100? |
| 21:19.08 | rmudgett | I'm not THAT archaic. :) |
| 21:20.29 | rmudgett | I think libsrtp used to only be a static library. Asterisk only needs the one linked in copy in res_srtp. |
| 21:20.58 | gtjoseph | could be |
| 21:22.46 | rmudgett | Anyway, I now have asterisk using the bundled pjproject |
| 21:24.21 | gtjoseph | cool. now look at chan_sip:build_peer line 31120 in current 13. |
| 21:25.55 | gtjoseph | rmudgett: you owe me ^^ |
| 21:35.44 | rmudgett | gtjoseph: This where it is setting the delme flag? |
| 21:35.54 | gtjoseph | correct |
| 21:36.04 | gtjoseph | got it in front of you? |
| 21:36.35 | rmudgett | yes |
| 21:36.58 | gtjoseph | ok, so we set all mailboxes to deleteme |
| 21:37.29 | rmudgett | That would be the mark of mark and sweep |
| 21:37.32 | gtjoseph | now if we don't have any variables skip down to 31059 |
| 21:38.06 | gtjoseph | we delete them all |
| 21:38.14 | gtjoseph | why? |
| 21:38.27 | gtjoseph | i think i know th eoriginal intent |
| 21:38.27 | file | 31059 is up, not down |
| 21:38.49 | file | or down not up, depending on your perspective :D |
| 21:39.01 | gtjoseph | i hate this file |
| 21:39.22 | coreyfarrell | he's a smart ass but I don't hate him |
| 21:39.24 | file | peers can be reused? they aren't recreated on a reload? |
| 21:39.54 | gtjoseph | let's just stick to the mailboxes |
| 21:40.05 | gtjoseph | on 31120 we mark them |
| 21:40.17 | file | we mark any existing mailboxes. |
| 21:40.48 | gtjoseph | now if we have no variables(v), skip down to 31569 |
| 21:40.59 | file | yes... |
| 21:41.06 | gtjoseph | we delete ALL of them |
| 21:41.21 | file | we delete all marked mailboxes, yes |
| 21:41.28 | gtjoseph | but they were all marked |
| 21:42.01 | gtjoseph | if your editor allows, collapse the huge for statement |
| 21:42.12 | file | if you have no new mailboxes, yes |
| 21:42.34 | gtjoseph | really tell me where that determination is done? |
| 21:43.15 | gtjoseph | in every stack trace i've seen v and alt are NULL |
| 21:43.26 | gtjoseph | so that loop should not be executed |
| 21:44.09 | file | that for loop is the complete logic for building a peer, it can't always be null |
| 21:44.27 | gtjoseph | it is for a peer that was in the cache |
| 21:44.58 | coreyfarrell | v will (always?) be NULL after the loop is finished |
| 21:45.15 | gtjoseph | it's NULL in the function parameters |
| 21:45.40 | gtjoseph | it's not reconstructing the peer, it pulled the peer from the cache based on name |
| 21:46.35 | gtjoseph | line 31036 |
| 21:47.08 | rmudgett | There are no other references to the mailbox->delme member anywhere in chan_sip. |
| 21:47.15 | gtjoseph | yes |
| 21:47.17 | rmudgett | gota go |
| 21:47.20 | gtjoseph | which is another problem |
| 21:47.30 | coreyfarrell | can I see the backtrace? |
| 21:47.46 | gtjoseph | #0 0x00007f28f00c363c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 |
| 21:47.46 | gtjoseph | #1 0x000000000053c445 in __ast_cond_wait (filename=0x6f262b "stasis.c", lineno=587, func=0x6f2e00 "stasis_subscription_join", cond_name=0x6f26ee "&subscription->join_cond", mutex_name=0x6f26c8 "ao2_object_get_lockaddr(subscription)", cond=0x7f28d801b1d0, t=0x7f28d801b130) at lock.c:600 |
| 21:47.46 | gtjoseph | #2 0x00000000005cfc1a in stasis_subscription_join (subscription=0x7f28d801b188) at stasis.c:586 |
| 21:47.46 | gtjoseph | #3 0x00000000005cfd0e in stasis_unsubscribe_and_join (subscription=0x7f28d801b188) at stasis.c:614 |
| 21:47.47 | gtjoseph | #4 0x00007f28a9684455 in destroy_mailbox (mailbox=0x7f28d8016b40) at chan_sip.c:5191 |
| 21:47.48 | rmudgett | Something should clear that flag but nothing does |
| 21:47.48 | gtjoseph | #5 0x00007f28a9710c51 in build_peer (name=0x7f28d8006310 "6012", v=0x0, alt=0x0, realtime=1, devstate_only=0) at chan_sip.c:31551 |
| 21:47.48 | file | the purpose of the delme stuff is to ensure that on a reload if a mailbox is removed then it is removed from the peer |
| 21:47.51 | gtjoseph | #6 0x00007f28a96857e2 in realtime_peer (newpeername=0x7f28d8006310 "6012", addr=0x0, callbackexten=0x0, devstate_only=0, which_objects=3) at chan_sip.c:5620 |
| 21:47.53 | file | rmudgett, indeed |
| 21:47.54 | gtjoseph | #7 0x00007f28a9685e1d in sip_find_peer_full (peer=0x7f28d8006310 "6012", addr=0x0, callbackexten=0x0, realtime=1, which_objects=3, devstate_only=0, transport=0) at chan_sip.c:5715 |
| 21:47.57 | gtjoseph | #8 0x00007f28a9685edf in sip_find_peer (peer=0x7f28d8006310 "6012", addr=0x0, realtime=1, which_objects=3, devstate_only=0, transport=0) at chan_sip.c:5754 |
| 21:48.00 | gtjoseph | #9 0x00007f28a96bf2b0 in mwi_event_cb (userdata=0x7f28d8006310, sub=0x7f28d801b188, msg=0x7f28d801c208) at chan_sip.c:17179 |
| 21:48.09 | file | the use of add_peer_mailboxes should set delme to 0 when the mailbox is read in |
| 21:48.13 | file | and it is a duplicate |
| 21:48.28 | gtjoseph | yep but i think the set and delete should only be done if v is provides |
| 21:48.30 | gtjoseph | provided |
| 21:48.48 | gtjoseph | and then add mailboxes should unset the flag if it finds it and it doesn't |
| 21:48.49 | file | the peer shouldn't be touched _at all_ |
| 21:48.59 | file | if v is empty |
| 21:49.28 | coreyfarrell | gtjoseph: unless you've seen that 'var' is NULL in realtime_peer that backtrace doesn't prove NULL was passed to build_peer. |
| 21:50.08 | gtjoseph | ah crap, true because v is modified directly on the stack |
| 21:50.22 | coreyfarrell | yeah that's what I was trying to say :) |
| 21:50.31 | file | coreyfarrell, dun dun dunnnnn |
| 21:51.14 | gtjoseph | actually there was a comment somewhere that name and v are mutually exclusive. |
| 21:51.20 | gtjoseph | gotta find it |
| 21:51.53 | file | like I said, without a list you can't alter the peer - can only be as-is |
| 21:52.18 | gtjoseph | ok, look at something else then... add_peer_mailbox |
| 21:52.55 | gtjoseph | if v isn't NULL then add_peer_mailboxes will be called if there are any mailboxes |
| 21:53.29 | gtjoseph | add_peer_mailboxes checks for dups but doesn't unset the delme flag |
| 21:53.34 | gtjoseph | if it finds one |
| 21:53.45 | gtjoseph | and it doesn't create a new one either |
| 21:53.56 | file | right, I believe it should set delme to 0 when the mailbox is read in and it is a duplicate |
| 21:54.36 | gtjoseph | ok then maybe that explains why the delete_mailbox is being called for every invocation of build_peer |
| 21:55.02 | gtjoseph | it's all those deletes piling up that's causing the lockup. |
| 21:56.37 | coreyfarrell | weird, wouldn't that cause mailboxes to cycle? first load it would skip creating because of the 'duplicate', then the delme would be caught and it would be deleted? |
| 21:57.19 | gtjoseph | it does heavily |
| 21:57.41 | gtjoseph | new mailbox and new subscription every time the peer is references |
| 21:58.24 | coreyfarrell | no, I mean if I have mailbox=100 on a peer, when chan_sip loads it will add '100' to peer->mailboxes. |
| 21:59.13 | coreyfarrell | then on reload it will set delme on the peer->mailbox for 100, add_peer_mailboxes would detect the duplicate, skip it, then build_peer would delete the mailbox (still flagged with delme). |
| 21:59.15 | gtjoseph | no because the list is cleared |
| 21:59.46 | gtjoseph | 31574 |
| 22:00.36 | coreyfarrell | that's after add_peer_mailboxes is called from 31352 |
| 22:02.06 | gtjoseph | didn't follow |
| 22:02.20 | coreyfarrell | 1) mailbox->delme is set at 31123, 2) add_peer_mailboxes called at 31352 but the mailbox hasn't been removed yet so we skip the duplicate, 3) mailbox->delme is still set, so we delete it |
| 22:02.57 | gtjoseph | correct |
| 22:03.03 | gtjoseph | =bad |
| 22:03.29 | gtjoseph | add_peer_mailbox needs to clear the delme flag |
| 22:03.48 | gtjoseph | when it detects that the mailbox is already in the list |
| 22:03.53 | coreyfarrell | yup |
| 22:07.28 | coreyfarrell | that's not going to fix a deadlock with stasis though, just make it less likely to happen. example if a mailbox was removed from config since last refresh it'll deadlock. |
| 22:07.39 | gtjoseph | true |
| 22:40.01 | coreyfarrell | gtjoseph: I think I've got an idea how to fix the deadlock, you got a few minutes? |
| 22:41.46 | gtjoseph | absolutely |
| 22:42.34 | coreyfarrell | ok so in this case we don't actually *need* stasis_subscription_join to run before ast_free(mailbox), we just need it to run before the module unloads. |
| 22:42.57 | gtjoseph | makes sense |
| 22:43.43 | coreyfarrell | stasis could provide a module version of stasis_unsubscribe which would add the subscription we're closing to a list associated with the module (internal to loader.c) |
| 22:44.31 | coreyfarrell | then loader.c would handle stasis_subscription_join of any remaining subscriptions at unload |
| 22:44.39 | coreyfarrell | module unload that is |
| 22:45.53 | gtjoseph | hmmm. why not just loop through all the peers in module_unload to destroy the mailbox subscriptions before destroying the peers themselves |
| 22:47.10 | coreyfarrell | that wouldn't protect from mailboxes that are already being destroyed due to a realtime refresh |
| 22:47.48 | gtjoseph | it would if it did the join, no? |
| 22:49.03 | coreyfarrell | destroy_mailboxes can't call stasis_subscription_join because it can be called from mwi_event_cb |
| 22:49.32 | file | right, I believe gtjoseph is saying that the unload would explicitly call the join variety instead |
| 22:49.52 | gtjoseph | correct and the original destroy_mailbox would only unsubscribe |
| 22:51.13 | coreyfarrell | isn't it possible that another thread could have just called destroy_mailbox because of realtime refresh and the unsubscribe hasn't finished yet? so in theory the final message for that subscription could come in after dlclose. |
| 22:51.30 | gtjoseph | define " realtime refresh" |
| 22:51.39 | coreyfarrell | your backtrace. |
| 22:53.09 | coreyfarrell | if that just called stasis_unsubscribe instead of stasis_unsubscribe_and_join, the thread running unload_module could finish before the final message associated with the subscription closed via mwi_event_cb -> sip_find_peer -> realtime_peer |
| 22:53.24 | gtjoseph | shouldt there be a check when a message is de-queued that if the subscription has been unsubscribed the callback should be ignored? |
| 22:54.16 | coreyfarrell | no, the final message is always sent |
| 22:54.21 | gtjoseph | i asked this question about 4 hours ago and no one responded |
| 22:54.33 | gtjoseph | to whom? |
| 22:54.46 | file | calling unsubscribe twice... is not something that is probably defined and would probably explode |
| 22:54.59 | gtjoseph | not saying that |
| 22:55.34 | gtjoseph | if there are pending messages for me and I unsubscsribe |
| 22:55.47 | gtjoseph | should those messages still get delivered? |
| 22:55.47 | coreyfarrell | mwi_event_cb receives the final message for it's own subscription, that's what the 'if (stasis_subscription_final_message(sub, msg)) {}' block handles. |
| 22:56.41 | gtjoseph | yes but it's too late then |
| 22:56.49 | gtjoseph | stasis needs to not call the callback |
| 22:57.00 | file | in what case? |
| 22:57.48 | gtjoseph | i'm trying to follow the case you guys are presenting where an unload might remove the function that a message callback might need |
| 22:58.22 | gtjoseph | if i unsubscribe and stasis doesn't call the callback isn't that a solution |
| 23:00.11 | file | that's a case coreyfarrell is presenting, with the build_peer fixed I don't see how it could happen if at unload it still does unsubscribe and join |
| 23:00.45 | gtjoseph | ah, ok. |
| 23:01.22 | coreyfarrell | file: I'm saying that another thread (not the unload) could delete the mailbox due to mwi_event_cb / sip_find_peer, and you guys are talking about not joining in that case right? |
| 23:01.35 | file | right, but how would it do that? |
| 23:02.17 | coreyfarrell | I don't understand your question |
| 23:02.28 | file | in what scenario would that occur with the build_peer function fixed? |
| 23:02.54 | coreyfarrell | if the mailbox=100,102 changed to mailbox=100 since the last realtime lookup? |
| 23:03.33 | file | if caching is enabled it wouldn't know it changed if I remember, and if caching isn't enabled then it wouldn't be subscribed? |
| 23:04.24 | gtjoseph | correct on both i think |
| 23:05.54 | gtjoseph | and only 102 would be affected |
| 23:06.07 | coreyfarrell | ah ok. so what I'm describing could only be caused by an actual 'sip reload' and if you do that right as you are unload the module bad things happen |
| 23:06.24 | file | the reload happens in the monitor thread |
| 23:06.44 | file | which should be terminated / unload blocked waiting on |
| 23:08.26 | file | I suppose that is arguably one of the saner things in that |
| 23:10.25 | gtjoseph | do the cleanup just after all the worker threads are dead or before you think? |
| 23:10.50 | file | that requires more thought than I have presently |
| 23:10.55 | gtjoseph | :) |
| 23:16.46 | coreyfarrell | what worker threads are you talking about? |
| 23:17.06 | gtjoseph | the sip workers |
| 23:21.29 | gtjoseph | and the issue just got pushed to add_peer_mwi_subs but that's all i have patience for tonight. :) |
| 23:23.12 | *** part/#asterisk-dev kharwell (kharwell@nat/digium/x-cyqvdtcwdwpntqif) |
| 23:25.50 | coreyfarrell | chan_sip.c is frustrating |