| 04:56.02 | *** join/#asterisk-dev tuxd00d (~tuxd00d@ip68-106-11-138.ph.ph.cox.net) |
| 06:01.57 | *** join/#asterisk-dev CELYA_ (~Thunderbi@LStLambert-657-1-90-73.w80-13.abo.wanadoo.fr) |
| 06:53.50 | *** join/#asterisk-dev tsearle (~tsearle@37.19.10.33) |
| 06:53.50 | *** mode/#asterisk-dev [+o tsearle] by ChanServ |
| 07:02.45 | *** join/#asterisk-dev tsearle (~tsearle@37.19.10.33) |
| 07:02.45 | *** mode/#asterisk-dev [+o tsearle] by ChanServ |
| 07:05.09 | *** join/#asterisk-dev tsearle (~tsearle@37.19.10.33) |
| 07:05.09 | *** mode/#asterisk-dev [+o tsearle] by ChanServ |
| 07:14.14 | *** join/#asterisk-dev tsearle (~tsearle@37.19.10.33) |
| 07:14.14 | *** mode/#asterisk-dev [+o tsearle] by ChanServ |
| 07:27.19 | *** join/#asterisk-dev pchero_work (~pchero@109.70.54.56) |
| 07:28.03 | *** join/#asterisk-dev hehol (~hehol@gatekeeper.loca.net) |
| 10:45.02 | *** join/#asterisk-dev CELYA_ (~Thunderbi@LStLambert-657-1-90-73.w80-13.abo.wanadoo.fr) |
| 10:57.44 | dan_j | I'm still trying to diagnose a problem I'm having. Please can someone explain this line? Re-wrote Contact URI host/port to X.X.X.X:5060 |
| 10:57.59 | dan_j | It seems to only show up when asterisk stops responding to sip packets |
| 10:58.51 | gtjoseph | That message happens when you have rewrite_contact turned on for an endpoint |
| 10:59.22 | gtjoseph | the contact gets re-written to the actualk ip address and port the request came from |
| 10:59.38 | gtjoseph | rather than what's specified in the Contact header |
| 11:01.40 | dan_j | In this case, the X.X.X.X is always the public IP of the asterisk server. That sounds a little odd to me that there is a local contact. Unless I've misunderstood something. |
| 11:01.54 | dan_j | I do have pacemaker running with sipsak but thats to 127.0.0.1 |
| 11:02.36 | gtjoseph | hmmm. that's not right. do you actually have rewrite_contact turned on for any endpoints? |
| 11:03.36 | gtjoseph | rmudgett recently did some work in that area but it's still early for him. |
| 11:04.10 | file | that message is output for rewriting an outgoing Contact if external_signaling_address is set |
| 11:04.15 | gtjoseph | oh, this is on outgoing messages. |
| 11:04.27 | gtjoseph | yeah, i just had to look at the code |
| 11:06.35 | dan_j | I've got rewrite_contact=yes |
| 11:06.56 | dan_j | external_signaling_address is not set in my config |
| 11:07.27 | gtjoseph | how aboutr the bind address in the transport |
| 11:07.42 | gtjoseph | actually external signalling address is also transport |
| 11:08.01 | dan_j | the bind address is set to the public ip |
| 11:08.20 | dan_j | it's actually a virtual ip that is moved by pacemaker when one machine is down |
| 11:09.32 | gtjoseph | that's it |
| 11:10.21 | dan_j | Please can you explain? It isn't moving when there is an issue. |
| 11:11.02 | gtjoseph | how does pacemaker update asterisk with the new address? |
| 11:11.41 | dan_j | No. Asterisk is not running on the secondary machine. If the primary machine goes down, pacemaker kills it and moves the IP to the secondary machine, and only then starts asterisk. |
| 11:12.58 | gtjoseph | yeah but does pacemaker modify the transport definition with the public ip address then start asterisk? |
| 11:13.40 | dan_j | No. The bind ip in the transport config on both servers is the same virtual ip, so no modifications are required. Just move the ip to the correct machine and then start asterisk so it binds to that IP |
| 11:14.16 | gtjoseph | oh gotcha |
| 11:14.36 | gtjoseph | so when you say "it isn't moving" what do you mean? |
| 11:15.20 | dan_j | "it isn't moving" = the public IP hasn't changed, so I'm not sure what's causing the"Re-wrote Contact URI host/port" messages |
| 11:15.40 | dan_j | "Re-wrote Contact URI host/port" may be totally unrelated to the downtime, but it only shows up when asterisk isn't responding to sip packets |
| 11:16.10 | dan_j | I dont think it's a network issue because it doesnt even respond via 127.0.0.1 |
| 11:16.20 | gtjoseph | ah, let me look at the code real quick |
| 11:16.25 | dan_j | thanks so much! |
| 11:21.19 | dan_j | I'm not sure it's an asterisk bug, as i've been running this version of asterisk for a couple of months now without this issue occurring. It could be a network issue that has exposed an asterisk bug, but the network config hasnt changed either. |
| 11:23.33 | gtjoseph | it looks like that debug message is always going to be logged on request messages that aren't a REGISTER or where cseq is 0 or response messages that aren't 3XX |
| 11:23.52 | gtjoseph | even it it's not actually re-written |
| 11:23.59 | gtjoseph | so it's a little misleading |
| 11:24.12 | dan_j | ok. so it doesn't help with diagnosing the issue. :( |
| 11:24.25 | gtjoseph | sorry |
| 11:24.56 | dan_j | so time to start sip logging to see whats coming in. maybe there is a malformed packet or something being sent to me |
| 11:25.25 | dan_j | although it is always going to be logged, it's still interesting that its only logged when this issue occurs. |
| 11:25.29 | gtjoseph | is asterisk not responding to any sip messages? |
| 11:25.47 | dan_j | correct. no response to any messages. |
| 11:25.58 | gtjoseph | hmmm |
| 11:26.29 | gtjoseph | well that message implies that asterisk is at least trying to send them |
| 11:30.42 | dan_j | ok. i'm going to turn debug and sip debug and wait for it to occur again |
| 11:36.47 | *** join/#asterisk-dev joshelson (~joshelson@206.81.147.110) |
| 12:28.01 | dan_j | gtjoseph: got a different debug message this time, no sip packets were logged when it was occurring. I had about 10 seconds of this: audiohook.c: Read factory 0x7fe9c8024848 and write factory 0x7fe9c8025288 both fail to provide 160 samples |
| 12:28.54 | dan_j | i had a ping test running to 8.8.8.8 while the outage occurred and there was no packet loss on that. |
| 12:29.13 | gtjoseph | can't say on the audiohook thing |
| 12:29.36 | gtjoseph | can you tcpdump or wireshark on the server? |
| 12:30.05 | dan_j | actually, ignore that. that message occurs throughout my logs |
| 12:30.24 | dan_j | yes. just 5060 or all traffic? |
| 12:31.41 | gtjoseph | i'd start with just 5060 |
| 12:35.03 | dan_j | i ran tcpdump on our firewall yesterday capturing the traffic from my monitoring provider. all it showed was that occasionally there was a 6 to 10 second detail for asterisk to respond. |
| 12:35.10 | dan_j | i'm capturing the traffic now on the server. |
| 12:42.41 | gtjoseph | was asterisk compiled with DONT_OPTIMIZE and BETTER_BACKTRACES? |
| 12:42.44 | dan_j | ok, it just happened again. it seems that during the outage, asterisk is still able to send a couple of OPTIONS but doesnt respond to inbound REGISTERs or INVITEs |
| 12:43.02 | dan_j | after the outage, it pushes out all the OKs etc |
| 12:43.05 | dan_j | but its too late |
| 12:43.34 | gtjoseph | use ast_coredumper to get a dump of the running asterisk while it appears hung |
| 12:44.08 | gtjoseph | if you can also use DEBUG_THREADS, ast_coredumper will also dump the locks table |
| 12:44.32 | dan_j | do I need to manually run that while the outage is ongoing? timing it is going to be difficult |
| 12:44.43 | gtjoseph | yeah, that's the only way |
| 12:44.58 | dan_j | does it cause additional downtime when running coredumper? |
| 12:45.17 | dan_j | ie. does it suspend asterisk while its dumping? |
| 12:45.35 | gtjoseph | yes it does but if it's not responding to packets anyway... |
| 12:45.44 | gtjoseph | the dump takes about 10-15 seconds |
| 12:48.38 | *** join/#asterisk-dev newtonr (newtonr@nat/digium/x-zksgsoccljbuughk) |
| 12:48.38 | *** mode/#asterisk-dev [+o newtonr] by ChanServ |
| 12:49.04 | dan_j | Ok. I'll have to recompile over the weekend with DEBUG_THREADS |
| 12:49.27 | file | don't do DEBUG_THREADS |
| 12:49.32 | gtjoseph | we can still get useful info as long as dont_optimize and better_backtraces are set |
| 12:49.35 | file | just DONT_OPTIMIZE and BETTER_BACKTRACES |
| 12:50.14 | dan_j | Ok. I'll do that this weekend and see what happens. Annoyingly, this issue only occurs during the day! |
| 13:07.51 | dan_j | can i do 'core show locks' during the outage to see anything useful, or is it the coredump that is required? |
| 13:08.11 | dan_j | oh, never mind, it's not a valid command |
| 13:11.40 | gtjoseph | it's only enabled when DEBUG_THREADS is on |
| 13:15.49 | dan_j | ok. I'll give it a go this weekend. in the meantime, I'll continue hunting. |
| 13:24.04 | *** join/#asterisk-dev leedm777 (textual@nat/digium/x-wuiqntumumdjnqxw) |
| 13:24.04 | *** mode/#asterisk-dev [+o leedm777] by ChanServ |
| 13:56.47 | *** join/#asterisk-dev cresl1n (Adium@asterisk/libpri-and-libss7-expert/Cresl1n) |
| 13:56.47 | *** mode/#asterisk-dev [+o cresl1n] by ChanServ |
| 14:17.42 | *** join/#asterisk-dev DanQuinney (sid18169@gateway/web/irccloud.com/x-wgmydrqqyrxonzyx) |
| 14:38.07 | *** join/#asterisk-dev stefan27 (~stefan27@static-212-247-4-149.cust.tele2.se) |
| 14:52.08 | *** join/#asterisk-dev rmudgett (rmudgett@nat/digium/x-vtyzgzgtosenonot) |
| 14:52.08 | *** mode/#asterisk-dev [+o rmudgett] by ChanServ |
| 15:16.22 | gtjoseph | dan_j: i may be biased but please don't go back to chan_sip at least until we can take a look at a backtrace and locks file. :) |
| 15:25.49 | dan_j | unfortunately, the frequency seems to be increasing. I'll have to move back to chansip for now. I'll try to set up a 2nd batch of servers running pjsip for testing. hopefully the issue will repeat on those, but i doubt it because it only seems to be occuring during the day (peak times) |
| 15:26.34 | gtjoseph | rats, ok |
| 15:26.56 | gtjoseph | is this the same version of asterisk you've been running? |
| 15:27.07 | dan_j | sucks really. spent about 2 years on pjsip to have to go back to chansip. |
| 15:27.29 | dan_j | but it's never been smooth sailing, so i think it's wise to move my production servers back to chansip. |
| 15:27.39 | gtjoseph | can't blame you |
| 15:27.40 | dan_j | I'm running a version of 13. not changed in 2 months. |
| 15:27.51 | dan_j | Asterisk GIT-13-13.15.0-rc1-149-g6383d92M |
| 15:28.07 | dan_j | I think i pulled a bug fix or something 2 months ago which is why it's like that |
| 15:28.27 | gtjoseph | ok, but it's been that version for a while right? |
| 15:29.24 | dan_j | Yes |
| 15:29.44 | dan_j | Was working fine. Right now its freezing every 5 minutes |
| 15:30.19 | dan_j | On two servers. Not sure why they are both increasing their frequency together. |
| 15:30.37 | gtjoseph | it's got to be some packet that's triggering the issue |
| 15:32.01 | gtjoseph | obviously tou have to get production stable but any data you can capture while the issue is happening, like a pcap, woul dbe a big help |
| 15:36.28 | seanbright | pffft. "stable" |
| 15:36.38 | seanbright | what fun is that?! |
| 15:38.52 | *** join/#asterisk-dev CELYA_ (~Thunderbi@2a01cb0583d31d00c4b0f05f2236c0a6.ipv6.abo.wanadoo.fr) |
| 15:46.34 | dan_j | gtjoseph: i can send you a small packet capture when it happened if that helps. |
| 15:46.59 | dan_j | I agree that its a packet because nothing has changed and dns looks fine. |
| 15:47.42 | gtjoseph | it'll help |
| 15:48.03 | gtjoseph | it'll be better if we can get one and a backtrace aty the same time when you get to testing |
| 15:56.39 | dan_j | I doubt I'll be able to do that period odds of catching it on a production server in order to run the core dump are low as it is. Odds of catching on a test server which has low usage... |
| 15:56.52 | dan_j | Period = . |
| 15:57.05 | dan_j | Voice typing while walking the dog |
| 16:11.15 | dan_j | How do I get the packet capture to you? I dont want to post it publicly. |
| 16:46.12 | *** join/#asterisk-dev joshelson (~joshelson@206.81.147.110) |
| 17:20.09 | *** join/#asterisk-dev leedm777 (textual@nat/digium/x-jvurygqbvyjuyrum) |
| 17:20.09 | *** mode/#asterisk-dev [+o leedm777] by ChanServ |
| 18:27.54 | *** join/#asterisk-dev cresl1n (Adium@asterisk/libpri-and-libss7-expert/Cresl1n) |
| 18:27.54 | *** mode/#asterisk-dev [+o cresl1n] by ChanServ |
| 18:29.02 | *** join/#asterisk-dev cresl1n (Adium@asterisk/libpri-and-libss7-expert/Cresl1n) |
| 18:29.02 | *** mode/#asterisk-dev [+o cresl1n] by ChanServ |
| 19:26.30 | *** join/#asterisk-dev pchero (~pchero@109.70.54.56) |
| 21:05.13 | *** join/#asterisk-dev jsmith (~jsmith@fedora/jsmith) |
| 21:05.13 | *** mode/#asterisk-dev [+o jsmith] by ChanServ |
| 21:05.54 | jsmith | Whee... looks like the MariaDB folks, in their infinite wisdom, decided to change the location of "mysql/mysql_version.h" to "server/mysql_version.h"... |
| 21:06.23 | jsmith | Time to try to hack something up to get Asterisk to look at the new location :-/ |
| 21:07.40 | seanbright | OR |
| 21:07.43 | seanbright | switch to res_odbc |
| 21:18.25 | jsmith | Well, it's not for me -- it's packaging for Fedora/CentOS/RHEL |
| 21:18.36 | jsmith | I don't use res_mysql personally... and haven't for many many years |