| 00:07.36 | wedhorn | snuff-work: event.c? any ideas on events in skinny that you may be using? |
| 00:09.11 | snuff-work | nah i think its purely a sip crash that 1 |
| 00:09.19 | snuff-work | nothing skinny related |
| 00:10.10 | wedhorn | sip writing over skinny session structures? |
| 00:11.26 | snuff-work | doubtful.. i have my other phone with DEADDEAD trying to 're-reg' with * doing a pcap to it atm to see what it says |
| 00:13.26 | wedhorn | did you use skinny reload? I had an issue before Christmas where a device wouldn't register after a skinny reload, but was in too much of a rush to investigate |
| 00:14.14 | wedhorn | had to restart asterisk and power cycle the phone to get things working again |
| 00:16.13 | snuff-work | k |
| 00:17.43 | snuff-work | http://pastebin.ca/2299897 |
| 00:17.56 | snuff-work | its now happy again.. (just skinny reload) |
| 00:20.34 | wedhorn | okay, the reload should remove sessions allowing new ones to come in (which appears the case) |
| 00:20.50 | snuff-work | but i did try that before with the other phone.. |
| 00:20.54 | wedhorn | the question is how 173.222.173.222 gets into the session structure in the first place |
| 00:20.57 | snuff-work | and it still failed to connect |
| 00:23.31 | wedhorn | it almost seems like we're freeing the session somewhere but continuing to use it |
| 00:24.10 | wedhorn | try turning on skinny debug packet and maybe see what causes the 'partial' unregister in the first place |
| 00:24.40 | snuff-work | mm.. is there a way to make it write that to a file ? |
| 00:24.42 | mjordan | yup. deaddead is put in to some free'd blocks as a hint that the memory has been reclaimed. If you're 'seeing' it, something is attempting to access memory that has already been deleted. |
| 00:24.48 | mjordan | snuff-work: yes. astmm. |
| 00:25.30 | mjordan | if you see something written to astmm other than 'new session', something has gone horrifically wrong :-) |
| 00:25.33 | wedhorn | mjordan: yep, just trying to work out what is initiating the free'ing |
| 00:26.01 | mjordan | snuff-work: wedhorn: is there anything other than the MWI subscription in whatever you're running? |
| 00:27.03 | snuff-work | i dont do mwi atm.. or not really 'setup' |
| 00:27.17 | wedhorn | I don't think I have MWI, but I do have some SLA hints stuff, but I'm not crashing |
| 00:27.36 | snuff-work | its a 2 test phone system with 3 sip trunks.. |
| 00:27.40 | snuff-work | i have 0 sla |
| 00:30.42 | mjordan | snuff-work: is there anything in the cache for MWI or DeviceState? CLI command 'event dump cache <MWI> <DeviceState>' |
| 00:31.41 | snuff-work | http://pastebin.ca/2299901 |
| 00:35.32 | mjordan | definitely strange. ast_event_destroy should only be called either by the event subsystem, or if something gets an event out of the cache - in which case they have to destroy it as a duplicate object is created for them. Doing a quick search (albeit quick), nothing is jumping out at me in trunk |
| 00:41.57 | wedhorn | mjordan: what would mmlog look like if a skinny structure was freed, event subsequently used it and freed it and then skinny starting writing over the same space? |
| 00:42.18 | mjordan | So, two random observations before I go: the crash occurs during a scheduled callback, and it occurs when deleting a hashtab object. The indicates that something was scheduled to delete a hint (hashtab is used almost exclusively by pbx.c) |
| 00:42.52 | mjordan | wedhorn: not entirely sure. Richard made some major changes to astmm and the mmlog to spit out a lot more stuff. It previously didn't display much. |
| 00:42.59 | mjordan | wedhorn: it's very much a poor man's valgrind |
| 00:43.52 | mjordan | but I imagine it would complain a lot. I'm guessing that skinny did a reload while something was already scheduled that would interact with a hint, and when it fired the pointer it had to the hint was already destroyed |
| 00:45.47 | wedhorn | my gut tells me that we're destroying a skinny_session but still using the memory (and what happens after can become rather random), or ^^^ |
| 01:31.18 | *** join/#asterisk-dev tzafrir_laptop (~tzafrir@212.179.75.202) |
| 01:31.19 | *** mode/#asterisk-dev [+o tzafrir_laptop] by ChanServ |
| 01:35.27 | *** join/#asterisk-dev mjordan (~mjordan@216.186.152.216) |
| 01:35.27 | *** mode/#asterisk-dev [+o mjordan] by ChanServ |
| 01:38.05 | jsmith | wedhorn: That sounds quite similar to the bug in chan_sip that was fixed in bug 20226 |
| 01:38.55 | jsmith | wedhorn: (chan_sip was using an address, stopped using it, something else came along and started using it, but something in chan_sip still referenced the old pointer) |
| 01:47.05 | wedhorn | jsmith: thanks, had a look. At the moment we're not aware of what action is causing the skinny issue, waiting for snuff to get another crash with some debugging on |
| 01:47.16 | jsmith | OK |
| 01:48.59 | wedhorn | https://issues.asterisk.org/jira/browse/ASTERISK-19663 may also be relevant (last comment), but given it only references the pointer and not the data, don't think so |
| 03:05.29 | *** part/#asterisk-dev mjordan (~mjordan@216.186.152.216) |
| 05:41.33 | *** join/#asterisk-dev tzafrir_laptop (~tzafrir@212.179.75.202) |
| 05:41.33 | *** mode/#asterisk-dev [+o tzafrir_laptop] by ChanServ |
| 07:03.11 | *** join/#asterisk-dev bulkorok (~bulkorok@85.183.36.36) |
| 07:15.09 | *** join/#asterisk-dev tzafrir_laptop (~tzafrir@212.179.75.202) |
| 07:15.09 | *** mode/#asterisk-dev [+o tzafrir_laptop] by ChanServ |
| 07:45.28 | *** join/#asterisk-dev hehol (~hehol@2001:1438:1009:200:d089:fa5d:458f:51f5) |
| 08:31.27 | *** join/#asterisk-dev schmidts (~schmidts@vie-086-059-105-021.dsl.sil.at) |
| 08:31.29 | schmidts | good morning |
| 09:44.37 | *** join/#asterisk-dev bombev (~bombev@PPPoE-Static-40-132.UnicsBG.Net) |
| 10:06.45 | *** join/#asterisk-dev tzafrir_laptop (~tzafrir@local.xorcom.com) |
| 10:06.45 | *** mode/#asterisk-dev [+o tzafrir_laptop] by ChanServ |
| 11:21.47 | *** join/#asterisk-dev italorossi (~italoross@187.60.66.11) |
| 12:33.23 | *** join/#asterisk-dev zerohalo (~zerohalo@74.61.196.236) |
| 12:35.31 | *** join/#asterisk-dev jmls (~somefake@77.107.171.82) |
| 13:31.46 | tzafrir_laptop | Looking at the recent security patch AST-2012-015 - doesn't it still allow unlimited Skinny cache entries? |
| 13:34.07 | tzafrir_laptop | Or is it limited to existing users the system knows? (entries of type Skinny/a@b) |
| 13:53.02 | *** join/#asterisk-dev w9sh (~chatzilla@64.238.96.125) |
| 13:55.31 | *** join/#asterisk-dev serafie (~erin@nat/digium/x-ibcqzdwvczdnxsqm) |
| 14:08.31 | *** join/#asterisk-dev mjordan (~mjordan@nat/digium/x-heryiddnuriyyofu) |
| 14:08.31 | *** mode/#asterisk-dev [+o mjordan] by ChanServ |
| 14:58.55 | *** join/#asterisk-dev leifmadsen (~Leif@asterisk/documenteur-extraordinaire/blitzrage) |
| 14:58.55 | *** mode/#asterisk-dev [+o leifmadsen] by ChanServ |
| 15:00.02 | *** join/#asterisk-dev bchia (~Adium@user-24-236-95-16.knology.net) |
| 15:34.02 | *** join/#asterisk-dev sruffell (~sruffell@asterisk/the-kernel-guy/sruffell) |
| 15:34.02 | *** mode/#asterisk-dev [+o sruffell] by ChanServ |
| 15:38.01 | *** join/#asterisk-dev leedm777 (~leedm777@nat/digium/x-poggxnrlyrcfqxby) |
| 16:06.41 | *** join/#asterisk-dev bchia (~Adium@nat/digium/x-rvomxedfcxcsvvaj) |
| 16:09.12 | *** part/#asterisk-dev bchia (~Adium@nat/digium/x-rvomxedfcxcsvvaj) |
| 16:11.05 | *** join/#asterisk-dev coreyf1513 (~cfarrell@ws2.cfware.com) |
| 17:18.38 | *** join/#asterisk-dev anthm (~anthm@freeswitch/developer/anthm) |
| 18:22.38 | *** join/#asterisk-dev philippel_mac (~p_lindhei@199.59.105.144) |
| 18:23.11 | philippel_mac | I'm curious if there is a reason nothing has ever been done with this bug: |
| 18:23.13 | philippel_mac | https://issues.asterisk.org/jira/browse/ASTERISK-17138 |
| 18:23.41 | philippel_mac | in a nutshell when a 403 is received by the sip channel, it never tries to register again without a sip reload or equivalent |
| 18:23.59 | philippel_mac | even if it is set to retry registrations indefinitely or for some repeated amount of times? |
| 18:29.21 | mjordan | so, first, any Asterisk open source developer could take on that bug if they wanted. As for why someone from Digium hasn't addressed it, it's in a priority queue. No one has gotten to it yet. |
| 18:30.51 | mjordan | Also: if I had to throw a wild guess out there, the patch merely comments out the AST_SCHED_DEL_UNREF. While that may change the behavior, it probably isn't the correct solution. I'd imagine that a better approach would be to honor the registerattempts setting and continue to attempt even if the provider sends a 403. |
| 18:31.43 | mjordan | Going a bit further: this isn't something you should see unless you have an error in your configuration. You attempt to register, and the provider sends you a "bad password". Unless you change your config with a new password and reload, you aren't ever going to succeed. The behavior that you're attempting to work around is already off nominal |
| 18:32.50 | mjordan | philippel_mac: are you guys seeing this scenario a lot? |
| 18:33.28 | philippel_mac | mjordan: hold on let me read |
| 18:33.39 | WIMPy | Unless it was a DNS issue. |
| 18:33.59 | WIMPy | That's where I've seen it. |
| 18:34.40 | mjordan | WIMPy: bad DNS records pointing to the wrong provider? |
| 18:34.52 | *** join/#asterisk-dev pabelanger (~pabelange@asterisk/contributor-and-bug-marshal/pabelanger) |
| 18:34.52 | *** mode/#asterisk-dev [+o pabelanger] by ChanServ |
| 18:35.01 | philippel_mac | mjordan: this has plagued Asterisk systems for year and I was helping in a scenario once where this root cause was finally uncovered |
| 18:35.11 | WIMPy | Happened when I was offline and the local catch-all came to play. |
| 18:35.12 | mjordan | philippel_mac: I'm fine with poking it in the queue |
| 18:35.19 | philippel_mac | there are different reasons why this error can come up |
| 18:35.43 | WIMPy | That's when I tried to put a final . to the hostnames, but as they also get sent in the SIP message, some providers dislike that. |
| 18:35.49 | philippel_mac | it is more often a 'carrier' issue where the carrier sends an inappropriate 403 back since in the 'normal' case you are right |
| 18:36.37 | WIMPy | I would assume it happens if your provider loses connectivity to some databases, just the same as it happens for access. |
| 18:36.45 | philippel_mac | I also did some looking around and it seems to be a 'grey' area in the spec but the net of it here, with the current settings, it's an asterisk bug because the settings are say to retry and yet asterisk is making a conclusive decision to stop because of the 403 |
| 18:37.01 | philippel_mac | WIMPy: that is an example where I have seen the issue |
| 18:37.12 | philippel_mac | thus the carrier recovers but the client never does |
| 18:37.19 | mjordan | totally agree that it's a bug. It's been low priority simply because it was assumed to be a rather odd corner case |
| 18:37.52 | philippel_mac | mjordan: I would refer to it as a long term plague that I've never found the root cause to for at least 3 years |
| 18:38.04 | philippel_mac | can't say I dug that deeply but ... |
| 18:38.34 | philippel_mac | I think a reasonable solution would be another sip setting, maybe at the trunk level but acceptable at the general settings level |
| 18:38.59 | philippel_mac | that says whether to 'honor' a 403 or not and stop bugging the carrier regardless of the retry setting or something of the sort |
| 18:40.16 | philippel_mac | let me add a comment to that ticket that may give some other reasonable suggestions and includes some comments from the sip implementation |
| 18:42.24 | *** join/#asterisk-dev marv (~Adium@173-14-206-193-huntsville.hfc.comcastbusiness.net) |
| 18:43.02 | mjordan | hm. In retrospect, I wonder why we'd ever cancel the registration attempts in handle_response_register. Ideally, I would imagine you'd just let sip_reg_timeout handle it. If it fails more than the configured amount, it will eventually stop trying to register. |
| 18:43.18 | philippel_mac | mjordan: seem the comments I added to the ticket |
| 18:45.05 | mjordan | philippel_mac: going over your comments from the SIP implementors, I would imagine that we wouldn't want to keep sending the REGISTER request. They make it sound as if the proper thing to do is stop sending and wait for manual intervention |
| 18:46.45 | philippel_mac | read the last comment which is that it shouldn't be hammered but it's ok to eventually try again |
| 18:47.51 | mjordan | right, in an hour :-). That's a long time for Asterisk to hold onto a scheduler subscription |
| 18:48.13 | philippel_mac | mjordan: I guess the crux here is that the user should be able to configure that, for example maybe |
| 18:48.30 | philippel_mac | sip403delay=1200 |
| 18:48.33 | mjordan | heh |
| 18:48.48 | mjordan | really, it feels like the existing "register always" parameter should be honored |
| 18:48.51 | philippel_mac | as in upon receiving a 403, don't retry for that amount of time |
| 18:49.18 | philippel_mac | well yes I think at a minimum that should be the case |
| 18:49.45 | philippel_mac | it's a matter of whether you want to go as far as to allow a user to configure something that modifies that upon a registration receiving a 403 |
| 18:50.35 | WIMPy | I'd express it as a factor on the normal retry timeout. |
| 18:50.39 | philippel_mac | if nothing is added then it should do as indicated, which is to keep trying at the configured interval |
| 18:50.42 | mjordan | that's a pretty specific dial to turn. If I can help it, I'd prefer to not have a setting for it, but I'm open to suggestions. I can poke on this in ye old priority queue - but if anyone would like to provide a patch that doesn't merely comment out the scheduler deletion, that'd help |
| 18:50.53 | pabelanger | +1 |
| 18:51.46 | leifmadsen | +2 |
| 18:51.54 | philippel_mac | I'd be perfectly happy if it was either as WIMPy indicates, or if you decide to hardcode it to something reasonable though I think 1hr is too long |
| 18:52.10 | philippel_mac | I think 5 minutes (unless they have specified longer) is reasonable |
| 18:53.27 | mjordan | some sort of back off at any rate. Issue has been poked in queue. No promises, but we'll take another look :-) |
| 18:54.07 | mjordan | but again, patches always help, and anyone who wants to can help move the issue along |
| 18:54.38 | pabelanger | talk is cheap, some me code :D |
| 18:54.53 | leifmadsen | code me some money |
| 18:54.54 | pabelanger | show* |
| 18:55.31 | philippel_mac | mjordan: I'm always happen to add patches where it fits within my skill set (e.g. queue pause patch recently) … messing with the sip channel for me would be a recipe for disaster and very ugly :) |
| 18:56.21 | mjordan | philippel_mac: it isn't you, it's chan_sip |
| 18:57.37 | philippel_mac | as an fyi, my point of bringing this up is that it has made Asterisk systems look flakey for years and gives us a bad rap, other client's have not appeared to be plagued by this issue so it's about 'improving our image' so to speak even when it was the carriers fault for sending a 403... |
| 20:22.12 | mjordan | leedm777: +1 on the review summary |
| 20:22.20 | leedm777 | :-D |
| 20:31.34 | *** join/#asterisk-dev tzafrir_laptop (~tzafrir@212.179.75.202) |
| 20:31.35 | *** mode/#asterisk-dev [+o tzafrir_laptop] by ChanServ |
| 22:25.04 | *** part/#asterisk-dev mjordan (~mjordan@nat/digium/x-heryiddnuriyyofu) |