| 02:38.59 | *** join/#asterisk-bugs tuxd00d (n=tuxd00d@128.187.132.25) |
| 03:38.10 | *** join/#asterisk-bugs DarkRift (i=dark@bas10-montreal02-1177582453.dsl.bell.ca) |
| 05:53.11 | *** join/#asterisk-bugs fakhir (n=fakhir@unaffiliated/fakhir) |
| 06:07.45 | *** join/#asterisk-bugs Deeewayne (n=dwayne@216.207.245.1) [NETSPLIT VICTIM] |
| 06:07.45 | *** mode/#asterisk-bugs [+o Deeewayne] by ChanServ |
| 06:51.27 | *** join/#asterisk-bugs oej (n=olle@soll4-125.cust.blixtvik.net) |
| 07:04.40 | *** join/#asterisk-bugs oej (n=olle@soll4-125.cust.blixtvik.net) |
| 09:27.10 | *** join/#asterisk-bugs mvanbaak (n=michiel@vanbaak.xs4all.nl) |
| 09:31.02 | *** join/#asterisk-bugs agx (n=AGX@host63-216-static.34-88-b.business.telecomitalia.it) |
| 10:00.59 | *** join/#asterisk-bugs mvanbaak (n=michiel@vanbaak.xs4all.nl) |
| 10:46.49 | *** part/#asterisk-bugs jmls (n=jmls@mail.tessera.co.uk) |
| 10:51.36 | *** join/#asterisk-bugs jmls` (n=jmls@mail.tessera.co.uk) |
| 10:58.04 | *** join/#asterisk-bugs oej (n=olle@soll4-125.cust.blixtvik.net) |
| 12:15.21 | *** join/#asterisk-bugs caio1982 (i=caio1982@CAcert-br/caio1982) |
| 13:33.18 | *** join/#asterisk-bugs putnopvut (n=putnopvu@216.207.245.1) |
| 13:33.18 | *** mode/#asterisk-bugs [+o putnopvut] by ChanServ |
| 13:55.43 | putnopvut | M12232 |
| 13:55.45 | MuffinMan | [assigned] [Asterisk] . I did not set the category correctly. 0012232: Deadlock on 1.4 pre-rc3, seems to be related either to chanspy, queue or devicestate reported by atis http://bugs.digium.com/view.php?id=12232 |
| 13:55.50 | putnopvut | fun one :) |
| 13:56.10 | putnopvut | file: so there's a deadlock that is happening because app_chanspy holds the channel lock, and then calls ast_read. |
| 13:56.45 | putnopvut | __ast_read has some deadlock avoidance built in regarding this channel lock, but it is for naught since chanspy already holds the lock. |
| 13:57.04 | file | where is it holding the lock? |
| 13:57.17 | putnopvut | The channel_spy function. |
| 13:57.36 | putnopvut | Line 244 in my checkout. |
| 13:58.02 | putnopvut | The core show locks output could probably be improved to show that the lock is actually held here. |
| 13:58.19 | file | once start_spying is called it is unlocked |
| 13:58.42 | putnopvut | hrmmm... |
| 14:00.13 | putnopvut | But the core show locks output is showing that thread 3034397584 is waiting on a lock that is being held by app_chanspy. |
| 14:01.50 | file | this would have been easier without trying to shut it down... |
| 14:02.31 | file | ponders |
| 14:02.41 | putnopvut | It's the shutdown that's causing the lock, it seems. |
| 14:02.53 | file | yeah |
| 14:03.41 | putnopvut | The problem is that there's obviously something wrong with core show locks, since the thread I mentioned earlier is supposedly waiting on the lock from app_chanspy but yet it is not shown as being locked anywhere in the output. |
| 14:04.06 | putnopvut | I suspect this is because one of the threads with the "tried and failed to get lock" already has that lock locked. |
| 14:06.18 | file | hrm |
| 14:06.37 | file | start_spying, that ast_softhangup... |
| 14:06.39 | putnopvut | You don't suppose that a masquerade could be behind this in some way? |
| 14:07.33 | file | I don't know 'bout that... |
| 14:07.57 | putnopvut | I'm just thinking about the timing involved, especially due to the new fixup function for the chanspy datastore. |
| 14:08.42 | file | I think a non-shutdowning core show locks is needed... and a bt would show whether a masquerade is happening... |
| 14:09.09 | file | thread 3034397584 is waiting on the lock for peer, while holding the lock on peer |
| 14:09.11 | file | erm |
| 14:09.15 | file | while holding the lock on chan |
| 14:09.26 | putnopvut | I don't think the masquerade is necessarily happening at the time, I just think it may have screwed up our reference in chanspy at a particularly bad moment. |
| 14:09.51 | putnopvut | Like we lock what we think is the spyee channel, then a masquerade occurs. Then it comes time to unlock, but we call unlock on the wrong channel. |
| 14:10.47 | file | the locking of the datastore and channel should prevent that |
| 14:11.15 | putnopvut | which channel locking are you referring to? |
| 14:11.33 | putnopvut | Oh, I see what you're saying. |
| 14:11.35 | putnopvut | ne'ermind. |
| 14:11.57 | file | so... what if something was holding the lock of peer, trying to get the lock of chan? that would cause a deadlock but I don't see 'dat here (just thinking) |
| 14:13.24 | file | ponders |
| 14:13.52 | file | wait, did I misread that? I think so |
| 14:13.58 | file | goes to get his glasses |
| 14:14.38 | file | better. |
| 14:15.00 | file | oh |
| 14:15.19 | file | ummm |
| 14:15.32 | file | we don't unlock spyee after the ast_check_hangup check |
| 14:15.55 | putnopvut | >_< |
| 14:16.11 | file | would you like to do the honors? |
| 14:16.18 | putnopvut | Sure, no prob. |
| 14:17.31 | file | this may not be the underlying deadlock issue, but it would cause the deadlock on shutdown |
| 14:18.47 | putnopvut | what underlying deadlock issue are you referring to? |
| 14:19.08 | putnopvut | Oh, I didn't read the description... |
| 14:19.32 | file | it would also cause it if you hung up at the right moment... |
| 14:20.36 | putnopvut | I think that's probably what caused it. |
| 14:20.52 | putnopvut | The core show channels command was trying to lock the channel that had hung up at the most inconvenient time. |
| 14:21.15 | file | nods |
| 14:21.18 | file | I concur |
| 14:22.13 | putnopvut | The queues were simply a red herring :) |
| 14:24.52 | putnopvut | Good find, btw! |
| 14:25.51 | file | buggggggggggs |
| 14:32.53 | file | AHA! |
| 14:34.24 | *** join/#asterisk-bugs fakhir (n=fakhir@unaffiliated/fakhir) |
| 14:36.51 | *** join/#asterisk-bugs lmadsen (n=Leif@asterisk/documenteur-extraordinaire/blitzrage) |
| 14:36.51 | *** mode/#asterisk-bugs [+o lmadsen] by ChanServ |
| 14:47.52 | *** part/#asterisk-bugs dwayne (n=dwayne@76.29.245.9) |
| 14:56.39 | mvanbaak | how to merge to 1.6.0 ? |
| 14:56.45 | mvanbaak | I committed a patch for 1.4 |
| 14:56.49 | mvanbaak | merged it to trunk |
| 14:56.57 | mvanbaak | but I think the patch should be in 1.6 as well |
| 14:57.19 | mvanbaak | when I try svnmerge -P trunk-merged I get loads of conflicts on other properties |
| 14:57.46 | Qwell | mergetrunk6 from repotools. you'll get a conflict on the properties.. if everything is okay with them, you can just svn resolved . |
| 14:57.59 | Qwell | well, conflict if 1.4>trunk>1.6.0 |
| 14:58.17 | mvanbaak | ah |
| 14:58.18 | mvanbaak | thanks |
| 14:59.39 | putnopvut | Qwell: I've never gotten a conflict... |
| 14:59.58 | Qwell | 1.4>trunk>1.6.0 you should |
| 15:00.11 | Qwell | just like 1.2>1.4>trunk |
| 15:00.34 | Qwell | because it tries to update a property that doesn't exist |
| 15:03.23 | mvanbaak | indeed |
| 15:03.27 | putnopvut | I've done that merge a few times and have not had a conflict. |
| 15:03.59 | mvanbaak | putnopvut: with the mergetrunk6 script or with plain svnmerge ? |
| 15:04.00 | putnopvut | Like the deadlock fixed earlier this morning...I had no conflict when merging from trunk to 1.6 |
| 15:04.06 | putnopvut | mergetrunk6 |
| 15:04.09 | mvanbaak | ah |
| 15:04.13 | mvanbaak | I tried svnmerge |
| 15:04.22 | mvanbaak | maybe mergetrunk6 fixes something ? |
| 15:04.28 | putnopvut | Perhaps. |
| 15:04.29 | file | returns with strawberry yogurt |
| 15:04.36 | putnopvut | Yum |
| 15:05.12 | mvanbaak | I'll try later today once I'm home |
| 15:05.44 | mvanbaak | it's a small fix so I can do it by hand, but that's not the way to do it :) |
| 15:38.28 | *** join/#asterisk-bugs Corydon76-lap (n=Corydon7@pdpc/supporter/bronze/Corydon76-home) |
| 15:38.28 | *** mode/#asterisk-bugs [+o Corydon76-lap] by ChanServ |
| 15:42.46 | *** join/#asterisk-bugs JunK-Y (n=junky@modemcable153.55-201-24.mc.videotron.ca) |
| 15:42.46 | *** mode/#asterisk-bugs [+o JunK-Y] by ChanServ |
| 16:09.17 | file | M12208 |
| 16:09.19 | MuffinMan | [new] [Asterisk] Channels/chan_sip/General 0012208: Calls drop due to unanswered INVITES reported by atrash http://bugs.digium.com/view.php?id=12208 |
| 16:09.20 | file | who was asking me about that... |
| 16:09.23 | file | putnopvut: you? |
| 16:11.37 | putnopvut | That was me, yes. |
| 16:12.08 | file | the Metaswitch is doing the right thing... oddly enough |
| 16:12.33 | putnopvut | Yeah, I never suspected that. |
| 16:12.44 | putnopvut | It just sounded like bad network conditions to me. |
| 16:12.57 | file | nods |
| 16:12.59 | file | it is. |
| 16:13.02 | file | oej: poke! |
| 16:13.04 | putnopvut | I looked through RFC 3261 to see if responses are supposed to be retransmitted. |
| 16:13.14 | oej | peek |
| 16:13.16 | putnopvut | And the only thing it said was that stateless UAS's should NEVER retransmit. |
| 16:13.25 | putnopvut | At least that's all I could find. |
| 16:13.30 | file | oej: why do we not send 200 OKs in response to a reinvite critically? |
| 16:13.34 | oej | YOu missed INVITEs then, putnopvout |
| 16:13.42 | oej | We should |
| 16:13.50 | file | we do not |
| 16:13.57 | oej | That's weird |
| 16:14.00 | file | indeed |
| 16:14.20 | oej | All responses to INVITEs should be critical, regardles of re-invite or invite |
| 16:14.24 | oej | we need that ACK |
| 16:14.26 | file | nods |
| 16:14.38 | file | aight |
| 16:14.50 | file | oej: thanks! |
| 16:15.16 | oej | Me changes |
| 16:15.24 | oej | We need retransmits |
| 16:15.44 | oej | But should not mark them critical if it's a re-invite... We should not hangup a call if a reinvite fails... I think. |
| 16:15.50 | oej | Depends on what we want to do. |
| 16:15.57 | oej | Hmm. Tricky. |
| 16:15.57 | file | this is for a reinvite from the remote side |
| 16:16.02 | file | so they send a reinvite to us |
| 16:16.08 | file | we send a 200 OK back unreliably |
| 16:16.11 | file | they never receive the 200 OK |
| 16:16.16 | file | they terminate the dialog |
| 16:16.19 | oej | We should send reliably |
| 16:16.22 | oej | But not critical |
| 16:16.36 | oej | Sorry, was deep into app_dial digging |
| 16:16.39 | file | nods |
| 16:16.42 | file | I'll take care of it |
| 16:16.58 | file | once your mind is in app_dial... it is best to stay there until done |
| 16:21.00 | Qwell | it's a trap. you can never be done with app_dial. |
| 16:28.33 | file | Qwell: you are a trap. |
| 16:30.16 | Juggie | why would mantis convert ~15 -> a bug note link? |
| 16:32.20 | Qwell | Juggie: because that's what it does :p |
| 16:33.49 | Juggie | ic |
| 17:07.16 | *** join/#asterisk-bugs jmls_home (n=jmls@mail.tessera.co.uk) |
| 17:17.05 | *** join/#asterisk-bugs seanbright (i=seanbrig@65.207.74.18) |
| 17:21.52 | *** join/#asterisk-bugs lmadsen (n=Leif@asterisk/documenteur-extraordinaire/blitzrage) |
| 17:21.52 | *** mode/#asterisk-bugs [+o lmadsen] by ChanServ |
| 17:25.22 | putnopvut | M12227 |
| 17:25.23 | MuffinMan | [assigned] [Asterisk] Applications/app_chanspy 0012227: Crash in chanspy_ds_destroy (__ast_pthread_mutex_unlock) reported by atis http://bugs.digium.com/view.php?id=12227 |
| 17:25.33 | putnopvut | file: I think you're right that this isn't solved by 12232's commit. |
| 17:25.56 | putnopvut | I think that perhaps the problem may reside in the fact that the ast_mutex_destroy at the end of common_exec is a bit...haphazard. |
| 17:26.10 | putnopvut | Perhaps adding a lock/unlock before would be safer? |
| 17:27.13 | putnopvut | Thoughts? |
| 17:27.16 | file | what do you think is happening? |
| 17:27.49 | putnopvut | I think that there's a miniscule chance that there's a race condition as follows: |
| 17:28.13 | putnopvut | The spyee channel hangs up, and so, through a series of functions, we get to chanspy_ds_destroy.l |
| 17:28.20 | putnopvut | The lock is acquired. |
| 17:28.48 | putnopvut | Then the app_chanspy thread destroys the lock. |
| 17:29.10 | putnopvut | Then the lock is attempted to be unlocked, but since the lock was just destroyed, no dice. |
| 17:29.21 | putnopvut | crash, in fact. |
| 17:29.24 | file | lock is acquired? |
| 17:29.32 | putnopvut | chanspy_ds->lock is locked. |
| 17:29.37 | file | that is bad. |
| 17:30.10 | putnopvut | Unfortunately that's all I've got at this point. |
| 17:30.20 | file | you can't destroy a mutex lock you have locked, big no-no |
| 17:30.56 | putnopvut | Well, that's the thing, it's not the same thread trying to lock and destroy the lock. |
| 17:31.08 | file | so hrm! |
| 17:31.11 | putnopvut | It's a race that I think may happen. |
| 17:31.17 | putnopvut | I'm trying to see just how possible that is. |
| 17:32.25 | file | nods |
| 17:33.28 | putnopvut | The thing is, I have eliminated (though perhaps erroneously) the possibility that the datastore is being freed out from underneath us while chanspy_ds_destroy is being called. |
| 17:33.52 | file | ooh the adventure continues |
| 17:34.11 | putnopvut | I would expect that if that were happening, then the chanspy_ds->lock would have a garbage address since when the datastore is freed, the datastore's data pointer is NULLed. |
| 17:34.38 | putnopvut | But the address seems legit in both backtraces, which makes me think that it's the mutex itself that is being destroyed out from under us. |
| 17:35.29 | file | it's not the fixup callback is it? |
| 17:35.55 | putnopvut | ^^ What does that "it" mean? |
| 17:36.14 | file | that could be unlocking when destroying |
| 17:36.44 | file | actually how can we get to a point where the datastore is in use elsewhere yet that function is falling through to the end... |
| 17:37.50 | putnopvut | In this case, I suspect that the "owner" thread (the sip thread for instance) hangs up, and then the pbx thread catches wind of it and destroys the mutex out from under the sip thread, which is attempting at that exact moment to destroy the datastore from the channel. |
| 17:38.30 | file | can you elaborate a bit more using spyee and spyer to reference each? |
| 17:39.42 | putnopvut | Okay, let's see if I can... |
| 17:40.00 | putnopvut | The spyee is on a call and the spyer starts to spy on it. |
| 17:40.11 | putnopvut | Now, the spyee hangs up. |
| 17:41.02 | putnopvut | The spyer sees that the spyee has hung up, and also hangs up. |
| 17:42.03 | putnopvut | Now, because the spyer has hung up, app_chanspy destroys the mutex lock for the chanspy_ds structure that is in the spyee's datastore. |
| 17:42.52 | putnopvut | It just happens to be that this mutex lock was destroyed at exactly the wrong time, right when the datastore's destroy callback (in this case chanspy_ds_destroy) was called. |
| 17:43.47 | putnopvut | And so it happens that the spyer's thread destroys the mutex while the spyee's thread still had it locked. |
| 17:44.17 | file | I don't know if that can happen... if spyer hangs up chanspy_ds_free should get called which removes it and such, do you think the channel is actually going through the same action at that time? |
| 17:45.14 | putnopvut | If that were the case, then there wouldn't be a race since chanspy_ds_free and chanspy_ds_destroy both lock the same lock. |
| 17:45.49 | file | so ast_channel_free locks/unlocks, deletes each datastore, locks/unlocks |
| 17:46.05 | putnopvut | Yes. |
| 17:46.34 | file | chanspy locks the datastore/locks channel/removes datastore and delete/unlocks channel/unlocks datastore/destroys mutex lock on datastore |
| 17:46.57 | putnopvut | which operation are you talking about? |
| 17:47.05 | file | chanspy_ds_free |
| 17:47.20 | putnopvut | I'm thinking that chanspy_ds_free isn't even entering into this. |
| 17:47.25 | *** join/#asterisk-bugs bbryant (n=brett@68.208.65.50) |
| 17:47.25 | *** mode/#asterisk-bugs [+o bbryant] by ChanServ |
| 17:47.39 | file | but that should be called when the spyer hangs up |
| 17:47.50 | putnopvut | not necessarily. |
| 17:47.54 | *** join/#asterisk-bugs lmadsen (n=Leif@asterisk/documenteur-extraordinaire/blitzrage) |
| 17:47.54 | *** mode/#asterisk-bugs [+o lmadsen] by ChanServ |
| 17:48.10 | putnopvut | If channel_spy returns 0, then that case is not explicitly handled. |
| 17:48.23 | file | ah! |
| 17:48.29 | putnopvut | Then the inner for loop would be broken out of, and since the spyer has hung up, then the outer for loop would be too. |
| 17:48.37 | *** join/#asterisk-bugs ACiDV (n=joel@122-205-229.dr.cgocable.ca) |
| 17:48.49 | file | yeah, you may have found it... |
| 17:49.01 | file | although even with what I said, the race condition could also happen if chanspy_ds_free was called |
| 17:49.13 | putnopvut | ORLY? |
| 17:49.24 | file | yes |
| 17:49.40 | putnopvut | I guess I'm not seeing how. |
| 17:50.25 | file | chanspy_ds_destroy could block waiting to acquire the datastore lock in ast_channel_free, chanspy_ds_free would complete and release the lock, then chanspy_ds_destroy would acquire it, but ast_mutex_destroy could have been called on that same mutex lock afterwards |
| 17:50.33 | file | s/afterwards/at the same time/ |
| 17:51.12 | putnopvut | Ah, I see what you're saying. |
| 17:54.24 | file | we could add a primitive refcount to this, and just wait until it is 0 to destroy |
| 17:55.01 | putnopvut | Yeah, a refcount is the safest thing to do. |
| 17:55.45 | file | start it off at 2 and bump it down in destroy and bump it down at the end, once it reaches 0 it is safe to proceed |
| 17:56.20 | putnopvut | Yuck... |
| 18:09.55 | *** join/#asterisk-bugs oej (n=olle@soll4-125.cust.blixtvik.net) |
| 18:13.44 | *** join/#asterisk-bugs fakhir (n=fakhir@unaffiliated/fakhir) |
| 18:34.01 | Juggie | what will the bug tracker say next to a file if a user has Attached a file to a bug, and has *NOT* submitted a license request at all. |
| 18:34.52 | file | License NONE? |
| 18:40.43 | Juggie | i dunno. |
| 18:41.19 | Juggie | we are close to breaking 300 bugs again. |
| 18:44.45 | file | hrm? |
| 18:44.54 | file | it's at 295... |
| 18:47.00 | Juggie | well thats close :P |
| 18:47.08 | Juggie | we were @ 286 a few days ago |
| 18:47.16 | file | it's Monday |
| 18:47.25 | Juggie | it sure is |
| 18:48.05 | JunK-Y | ive 292 here |
| 18:51.30 | file | putnopvut: aight, gonna take care of it? |
| 18:53.26 | JunK-Y | file: are you going to it360 this year? |
| 18:53.52 | file | I do not think so |
| 18:54.02 | JunK-Y | too bad :( |
| 18:54.12 | putnopvut | file: what, the ghetto refcount thing? |
| 18:54.19 | file | sure |
| 18:55.16 | *** join/#asterisk-bugs oej (n=olle@soll4-125.cust.blixtvik.net) |
| 18:59.18 | JunK-Y | how can ive messages like: [Mar 17 14:59:05] NOTICE[11882]: chan_iax2.c:6701 socket_read: Out of idle IAX2 threads for I/O, pausing! |
| 18:59.21 | JunK-Y | ive set to 300 |
| 18:59.25 | JunK-Y | and only have 100 channels. |
| 18:59.26 | file | deadlock. |
| 19:00.09 | JunK-Y | === Thread ID: 1683757408 (pbx_thread started at [ 2647] pbx.c ast_pbx_start()) |
| 19:00.12 | JunK-Y | === ---> Tried and failed to get Lock #0 (channel.c): MUTEX 2015 __ast_read &chan->lock 0x2aa70bbd18 (0) |
| 19:00.21 | JunK-Y | === Thread ID: 1687935328 (pbx_thread started at [ 2647] pbx.c ast_pbx_start()) |
| 19:00.25 | JunK-Y | === ---> Tried and failed to get Lock #0 (channel.c): MUTEX 2015 __ast_read &chan->lock 0x2aa36ccdc8 (0) |
| 19:00.28 | JunK-Y | yeah |
| 19:13.07 | Qwell | err |
| 19:13.09 | Qwell | M12199 |
| 19:13.11 | MuffinMan | [assigned] [Asterisk] Core/BuildSystem 0012199: configure script flaw on Solaris 10 (and maybe others) reported by dmartin http://bugs.digium.com/view.php?id=12199 |
| 19:13.13 | Qwell | it already uses gid O.o |
| 19:33.10 | *** join/#asterisk-bugs implicit (n=implicit@200.12.227.181) |
| 19:33.10 | *** mode/#asterisk-bugs [+o implicit] by ChanServ |
| 19:45.28 | putnopvut | So, file, here's something even more obvious that I should have thought of before but didn't. |
| 19:45.43 | putnopvut | The chanspy_ds structure that is stored in the channel datastore is not heap data. |
| 19:46.01 | putnopvut | It's stack data. It goes out of scope, and kaplooey...you're referencing bogus memory. |
| 19:49.16 | file | this is true. |
| 19:50.28 | putnopvut | So it may or may not have anything to do with the lock being destroyed. |
| 19:50.54 | file | see, the datastore *should not* be on the channel once that loop is broken... |
| 19:53.22 | putnopvut | But yet it seems possible. |
| 19:56.48 | file | offers putnopvut some strawberry yogurt |
| 19:57.00 | putnopvut | YUMMM! |
| 19:57.20 | file | I think I'm going to go grab a sub in a bit |
| 20:00.20 | putnopvut | Cool, dawg. |
| 21:28.49 | *** join/#asterisk-bugs Yourname`` (n=chatzill@unaffiliated/yourname/x-837320) |
| 21:29.09 | Yourname`` | Damn, this is the channel I should have been in! And I've been going on about the coredump in *-dev |