| 00:22.32 | *** join/#asterisk-dev jkroon (~jkroon@165.16.204.172) |
| 00:39.06 | *** join/#asterisk-dev sh_smith (foobar@cpe-76-174-26-91.socal.res.rr.com) |
| 04:36.32 | *** join/#asterisk-dev snuff-work (~snuff-wor@210.9.148.102) |
| 04:36.32 | *** mode/#asterisk-dev [+o snuff-work] by ChanServ |
| 04:45.06 | *** join/#asterisk-dev sh_smith (foobar@cpe-76-174-26-91.socal.res.rr.com) |
| 07:35.01 | *** join/#asterisk-dev joshelson (~joshelson@216.200.17.249) |
| 08:46.23 | *** join/#asterisk-dev pchero (~pchero@109.70.54.56) |
| 14:13.49 | dan_j | gtjoseph: are you around? |
| 14:13.57 | gtjoseph | yep |
| 14:16.46 | dan_j | Before I start making the switch back to chansip, did you manage to take a look at the packet capture? I just messaged you because i thought i saw something dodgy, but the packet I saw was from well before the outage. |
| 14:17.32 | gtjoseph | I didn't. It's on my list for today. I can take a look real quick righ tnow though. |
| 14:18.06 | dan_j | Thanks. |
| 14:19.14 | gtjoseph | about how far into the pcap did the issue start? |
| 14:21.21 | dan_j | Hard to say when it starts because pacemaker only runs a sipsak test every 60 seconds. The sipsak test started at around packet number 2656 which is 13:35:42 and received no response to each test. The sipsak was re-run every second and only received a response at 13:35:51. |
| 14:21.33 | dan_j | Note that the sipsak tests arent captured because they are sent to 127.0.0.1 |
| 14:22.03 | gtjoseph | ok. and the .87 address is the server? |
| 14:22.11 | dan_j | Correct |
| 14:23.07 | dan_j | You can see that at 13:35:48, asterisk pumps out all the challenge requests that were pending. |
| 14:23.44 | gtjoseph | looks like packet 2571 is the last one the server sends for a while |
| 14:24.52 | dan_j | It does send a couple of OPTIONS, even during the outage. |
| 14:25.00 | gtjoseph | yeah i just noticed that |
| 14:25.19 | gtjoseph | but those are handled in another thread |
| 14:25.41 | dan_j | ok. so that explains why the options are still working. |
| 14:26.14 | dan_j | Let me just see if the outages are still occurring. It usually only happens during the week day. |
| 14:28.00 | gtjoseph | the outage is exactly 15 seconds |
| 14:28.08 | dan_j | Last one was an hour ago for literally 2 seconds. But as i said yesterday, it's going to be very difficult to time the core dump with the outage |
| 14:28.16 | gtjoseph | and the server was able to actually send an invite during that time |
| 14:28.28 | gtjoseph | ok |
| 14:28.52 | dan_j | the one prior to that was 18 seconds. |
| 14:29.14 | gtjoseph | ok so the length isn't significant |
| 14:29.19 | dan_j | Just checking the other server i have running as that has higher usage at the weekends |
| 14:30.16 | dan_j | Same frequency on the other server, but different times. So I doubt its a network issue or dns as I would expect them to have issues at the same time |
| 14:30.55 | gtjoseph | yep |
| 14:33.34 | dan_j | I know you'd love more data on this, but at the moment, what are your thoughts regarding rescuing my pjsip setup? |
| 14:33.53 | dan_j | Either way, I need to get it stable by start of business tomorrow. |
| 14:34.20 | gtjoseph | give me a sec, i'm looking at an OK that I can't find a matching request for. |
| 14:34.27 | gtjoseph | it's packet 2573 |
| 14:35.14 | dan_j | 2568 |
| 14:35.41 | gtjoseph | oh man, my eyes must be going bad |
| 14:36.06 | dan_j | anyones would looking at a packet capture |
| 14:41.08 | gtjoseph | does user "admin" ring a bell? it makes a bunch of rejected calls. |
| 14:42.06 | dan_j | nope. what is the packet number? |
| 14:42.41 | gtjoseph | 590 |
| 14:43.54 | dan_j | Looks like a hack attempt judging by the user-agent and number dialled. |
| 14:44.52 | gtjoseph | yeah ok |
| 14:47.56 | gtjoseph | this looks interesting... starting at packet 508 |
| 14:48.32 | gtjoseph | oh no, nevermind |
| 14:50.05 | gtjoseph | it looks like another hit took place at packet 949 |
| 14:50.15 | gtjoseph | 4 incoming registers went unanswered |
| 14:51.55 | dan_j | Yeh, it was answered a while later at 1065? |
| 14:53.01 | gtjoseph | yep |
| 14:55.22 | gtjoseph | i take it "heartbeatpeer" is you |
| 14:55.43 | dan_j | the ones you can see are the external monitoring company running a test. |
| 14:56.05 | dan_j | i use the same peer for the local pacemaker tests too |
| 14:56.14 | gtjoseph | gotcha |
| 14:57.15 | gtjoseph | all of the subscribes are 404 not found. is this normal? |
| 14:58.12 | dan_j | yeh, they were configured for resource lists but i disabled them a while back when asterisk kept crashing due to a race condition. just not got round to re-enabling them |
| 14:58.22 | gtjoseph | gotcha |
| 15:03.20 | gtjoseph | hmmmmmm. look at packet 947 |
| 15:04.06 | gtjoseph | actually 944 |
| 15:04.32 | dan_j | Thats why I initially contacted you today, but it was from before the outage that i'd been notified about. I didnt realise the outages were occurring more often than that until you pointed out the 4 unanswered registers. |
| 15:04.43 | gtjoseph | ah |
| 15:04.49 | dan_j | 944 is from asterisk |
| 15:05.00 | gtjoseph | yeah it appears so |
| 15:05.08 | gtjoseph | but i've never seen it before |
| 15:05.15 | dan_j | 829 |
| 15:05.23 | dan_j | Seems like the first one from that IP |
| 15:06.12 | dan_j | I'm going to do another capture to see if they are still coming in. |
| 15:06.30 | dan_j | That IP doesnt appear to belong to a client |
| 15:06.33 | gtjoseph | wireshark decodes it as UTRAN IuBC interface SABP signaling |
| 15:06.40 | dan_j | yep |
| 15:09.08 | dan_j | Looks to be a UK mobile broadband IP |
| 15:10.48 | dan_j | But asterisk seems to be able to respond to it as there is nothing else listening on 5060, unless iptables is responding. |
| 15:11.27 | gtjoseph | do you have logs from that time? Can you see if there's anything interesting? |
| 15:11.33 | dan_j | Actually |
| 15:11.55 | gtjoseph | it's possible pjproject is doing something with it |
| 15:12.08 | gtjoseph | i have no idea what asterisk would do with it |
| 15:12.16 | dan_j | Look at packet 5346 for example. Can you see the raw ascii? It contains SIP data, but just a bit scrambled |
| 15:13.26 | gtjoseph | that's odd |
| 15:13.55 | gtjoseph | and 5347 contains a shifted response |
| 15:14.23 | dan_j | ok, so asterisk is dealing with it somehow |
| 15:14.39 | dan_j | Just doing a capture on a different server to see if it has similar packets |
| 15:15.12 | dan_j | might just be wireshark not decoding properly. |
| 15:15.34 | gtjoseph | possibly but there are other packets that are ok in between |
| 15:17.18 | gtjoseph | 5303 is a stun request. hmmm |
| 15:17.35 | dan_j | Nothing on either server right now |
| 15:19.11 | dan_j | 5303 is a known client. |
| 15:19.46 | gtjoseph | it's always that same ip for the SABP messages |
| 15:20.17 | dan_j | Yep. Looks like there was an issue with them. But they would only be affecting one server. |
| 15:20.30 | gtjoseph | why only 1? |
| 15:20.49 | dan_j | Clients are kept separate. Some on one cluster, some on another. |
| 15:21.04 | gtjoseph | gotcha. is this a know client though? |
| 15:21.08 | gtjoseph | known |
| 15:21.11 | dan_j | yep |
| 15:21.15 | gtjoseph | ok |
| 15:21.54 | dan_j | and as far as I can recall, i set up their devices before shipping them. |
| 15:22.21 | gtjoseph | ok, it's probably a red herring then |
| 15:35.00 | gtjoseph | dan_j: i saw at least 3 episodes just in that 1 pcap but nothing to indicate what the cause might be. |
| 15:35.17 | gtjoseph | can you tell me the threadpool settings for pjsip and stasis? |
| 15:35.55 | dan_j | where can I find them? |
| 15:36.20 | gtjoseph | Look at this page... https://wiki.asterisk.org/wiki/display/AST/Performance+Tuning |
| 15:36.41 | gtjoseph | if you haven't set them, then they're probably too low |
| 15:37.15 | dan_j | They aren't set. |
| 15:38.00 | dan_j | Although could they start being an issue on two servers at the same time if they have different load? |
| 15:38.14 | gtjoseph | alsdo, do a 'core show taskprocessors' |
| 15:38.19 | gtjoseph | maybe not |
| 15:38.41 | dan_j | But I like the look of 'threadpool_initial_size'. May help me with my startup issues. |
| 15:39.13 | gtjoseph | core show taskprocessors will tell you what the max backlogged tasks were for each taskprocessor |
| 15:39.31 | gtjoseph | run it now just to see |
| 15:39.43 | dan_j | max depth? |
| 15:39.47 | gtjoseph | yep |
| 15:40.18 | dan_j | most are below 50 |
| 15:40.28 | dan_j | but sorcery/contact_status-00000019 is 1364 |
| 15:40.30 | gtjoseph | it's easier to work with if you do 'asterisk -rx "core show taskprocessors" | less' |
| 15:41.16 | gtjoseph | hmmm |
| 15:41.30 | dan_j | https://pastebin.com/aEhGuGE7 |
| 15:41.34 | gtjoseph | that wouldn't cause this issue |
| 15:42.01 | gtjoseph | yeah that's fine |
| 15:42.39 | gtjoseph | has the server you run this on experienced the problem in the past? |
| 15:42.56 | gtjoseph | since it was last restarted that is |
| 15:43.03 | dan_j | never seen this issue. started 4 days ago on both machines at the same time. |
| 15:43.46 | gtjoseph | i mean, do you know if this particular system saw the issue today maybe? |
| 15:44.14 | dan_j | yes, this system had the issue today |
| 15:44.47 | gtjoseph | well, that really sucks because one train of thought we had was that the taskprocessors were getting backed up |
| 15:44.55 | gtjoseph | but they aren't |
| 15:46.20 | gtjoseph | usually its the pjsip/distributor ones that are the issue |
| 15:46.56 | gtjoseph | but they look fine |
| 15:49.29 | gtjoseph | well, nothing jumps out at me. Can you open an issue for this? Attach the taskprocessor list to it. I'll attach the pcap to the internal version of the issue so it's not public. Unfortunately, that's not going to help you for tomorrow. |
| 15:50.47 | dan_j | Ok. I'll open it. Hopefully, i'll be able to try our pjsip again another day, but if I make the move back, unfortunately, it won't be until the qualify and startup time is improved. |
| 15:50.57 | dan_j | thanks for all your help and time! |
| 15:51.18 | gtjoseph | i wish i coul dhave helped more |
| 15:51.51 | dan_j | No problem.Maybe someone else is experiencing something similar. I just help chansip doesnt have the same issue :S |
| 15:54.11 | *** join/#asterisk-dev jkroon (~jkroon@165.16.204.172) |
| 15:57.04 | dan_j | Are you able to attach the taskprocessor list internally as it contains valid usernames |
| 15:57.18 | gtjoseph | yep, send it to me in an email |
| 15:57.46 | dan_j | https://issues.asterisk.org/jira/browse/ASTERISK-27247 |
| 15:58.31 | dan_j | Sent |
| 15:58.38 | dan_j | Thanks |
| 16:11.48 | *** join/#asterisk-dev pchero (~pchero@109.70.54.56) |
| 17:00.47 | *** join/#asterisk-dev tzafrir (~tzafrir@local.xorcom.com) |
| 17:00.47 | *** mode/#asterisk-dev [+o tzafrir] by ChanServ |
| 18:05.44 | *** join/#asterisk-dev gtjoseph (~gtjoseph@unaffiliated/gtj) |
| 18:05.44 | *** mode/#asterisk-dev [+o gtjoseph] by ChanServ |
| 19:11.06 | gtjoseph | dan_j are you still around? |
| 19:11.12 | gtjoseph | might have some news |
| 19:16.15 | dan_j | Always |
| 19:16.43 | gtjoseph | richard found an issue in the taskrocessor dump |
| 19:17.23 | gtjoseph | subm:ast_device_state_topic-00000002 went over the high water mark and when that happens, pjsip stops accepting new requests |
| 19:18.45 | dan_j | Amazing! But strange it starts to be an issue on two systems at the same time. |
| 19:19.03 | gtjoseph | do you collect call detail records on those servers? |
| 19:19.48 | gtjoseph | and the hep modules? |
| 19:20.21 | dan_j | Normal cdrs? |
| 19:20.36 | gtjoseph | anything via the cdr_modules |
| 19:20.42 | gtjoseph | or the res_hep modules |
| 19:21.27 | dan_j | Ive got cdr csv enabled along with odbc cdrs to a local mysql server |
| 19:21.39 | gtjoseph | ok. how about the hep modules? |
| 19:21.52 | gtjoseph | these are just general things to reduce stasis load |
| 19:21.55 | dan_j | Dont think im doing anything with hep unless its doing something by default |
| 19:22.12 | gtjoseph | use noload in modules.conf to prevent them from loading. |
| 19:29.32 | dan_j | res_hep isn't loaded |
| 19:30.06 | dan_j | I've already got it as noload. Probably had issues with it in the past |
| 19:30.16 | gtjoseph | is there anything you can think of that would cause a delay in processing device state changes? |
| 19:31.20 | gtjoseph | or any changes relates to device state that might have happened |
| 19:33.10 | dan_j | Not off the top of my head. Nothing related to device state is realtime. it's all static. the only thing related to device state is custom devices, but nothing that would delay the processing of it |
| 19:33.59 | dan_j | When i was looking at the cli debug output during an outage, there weren't any mentions regarding device status that I can recall |
| 19:34.48 | gtjoseph | look for errors or warning about the taskprocessors |
| 19:35.07 | gtjoseph | i forget the exact message but yuou should get one each time a taskprocvessor goes over the high water mark |
| 19:35.50 | dan_j | verbose or debug? |
| 19:36.16 | gtjoseph | regular log. they should be warnings or wrrors |
| 19:38.27 | dan_j | No mention of 'processor' or 'task' in the logs in the last 3 days |
| 19:38.44 | gtjoseph | let me see if i can find the exact message |
| 19:39.15 | dan_j | found on |
| 19:39.17 | dan_j | one |
| 19:39.24 | dan_j | on asterisk startup on one of the servers |
| 19:39.52 | dan_j | No others following that |
| 19:39.54 | gtjoseph | ast_log(LOG_WARNING, "The '%s' task processor queue reached %ld scheduled tasks%s.\n", |
| 19:39.54 | gtjoseph | tps->name, tps->tps_queue_size, tps->high_water_warned ? " again" : ""); |
| 19:39.54 | gtjoseph | tps->high_water_warned = 1; |
| 19:44.22 | gtjoseph | hmmm. it's possible that the version you're running only spits the message the first time it happens |
| 19:46.01 | gtjoseph | dan_j: i have to run and i don't really have another short term syggestion, sorry. |
| 19:46.01 | dan_j | I could install 13.17.1. worried about moving to a new version and introducing some bugs. I've not been following the state of play. |
| 19:46.12 | gtjoseph | yeah i understand |
| 19:46.29 | gtjoseph | could you do 1 server? |
| 19:46.36 | dan_j | Yes. |
| 19:46.49 | gtjoseph | if anything we'll get more info |
| 19:46.52 | dan_j | How can I speed up the processing? Or is something simply getting stuck? |
| 19:47.23 | gtjoseph | that i don't know right now. i think foirst we need to confirm that it's happening at more times than startup |
| 19:47.55 | dan_j | Ok. I'll upgrade one machine and go from there. Thanks for your help. |
| 19:48.01 | gtjoseph | no problem |
| 20:28.15 | *** join/#asterisk-dev pchero (~pchero@109.70.54.56) |
| 21:31.18 | *** join/#asterisk-dev tzafrir (~tzafrir@bzq-179-40-170.cust.bezeqint.net) |
| 21:31.18 | *** mode/#asterisk-dev [+o tzafrir] by ChanServ |