SOLVED "Peer 'xx' is now Lagged" messages

[mcbsys]

Using CentOS 5.2, PiaF 1.3, Asterisk 1.4.21.2. Yeah it's old but it's been solid for years. Ancient hardware (PowerEdge 1500SC, RAID 5).

Small installation: three active extensions. Recently switched from copper to VoIP trunk.

Internet is DSL 3000/512, interleaved, tests at about 2600/410, or a bit lower when I turn on QoS on my Tomato router. VoIP line test from a Windows computer gives good results.

voip.ms says they don't see errors on their side.

Below are the warnings from one day.

How common/normal are these peer lagged messages? Users haven't complained, but usage is low. Would calls drop when the line is lagged? Would IAX be better? Do I need to try replacing the Ethernet card?

WARNINGS:
[Feb 23 10:34:08] VERBOSE[12256] logger.c: -- Called losangeles.voip.ms/8581234567
[Feb 23 10:34:14] VERBOSE[3147] logger.c: -- Got SIP response 486 "Busy Here" back from 67.215.241.250
[Feb 23 10:34:14] VERBOSE[12256] logger.c: -- SIP/losangeles.voip.ms-08c5b210 is busy

Unreachable or Lagged:
[Feb 23 04:20:08] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Lagged. (2343ms / 2000ms)
[Feb 23 04:20:18] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Reachable. (79ms / 2000ms)
[Feb 23 04:53:25] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Lagged. (3096ms / 2000ms)
[Feb 23 04:53:35] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Reachable. (79ms / 2000ms)
[Feb 23 10:37:10] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Lagged. (3061ms / 2000ms)
[Feb 23 10:37:20] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Reachable. (60ms / 2000ms)
[Feb 23 11:01:25] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Lagged. (2855ms / 2000ms)
[Feb 23 11:01:35] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Reachable. (66ms / 2000ms)
[Feb 23 11:50:44] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Lagged. (2893ms / 2000ms)
[Feb 23 11:50:54] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Reachable. (63ms / 2000ms)
[Feb 23 13:32:07] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Lagged. (2046ms / 2000ms)
[Feb 23 13:32:17] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Reachable. (63ms / 2000ms)
[Feb 23 14:46:28] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Lagged. (2100ms / 2000ms)
[Feb 23 14:46:38] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Reachable. (63ms / 2000ms)
[Feb 23 14:47:40] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Lagged. (2062ms / 2000ms)
[Feb 23 14:47:50] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Reachable. (60ms / 2000ms)
[Feb 23 18:24:16] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Lagged. (2449ms / 2000ms)
[Feb 23 18:24:27] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Reachable. (1063ms / 2000ms)
[Feb 23 18:25:29] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Lagged. (2062ms / 2000ms)
[Feb 23 18:25:39] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Reachable. (99ms / 2000ms)
[Feb 23 18:26:29] NOTICE[3147] chan_sip.c: -- Registration for '[email protected]' timed out, trying again (Attempt #2)
[Feb 23 18:29:41] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Lagged. (2062ms / 2000ms)
[Feb 23 18:29:51] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Reachable. (63ms / 2000ms)
[Feb 23 20:42:09] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Lagged. (2716ms / 2000ms)
[Feb 23 20:42:19] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Reachable. (60ms / 2000ms)
[Feb 23 21:31:30] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Lagged. (3363ms / 2000ms)
[Feb 23 21:31:40] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Reachable. (60ms / 2000ms)
[Feb 24 02:29:07] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Lagged. (3060ms / 2000ms)
[Feb 24 02:29:18] NOTICE[3147] chan_sip.c: Peer 'losangeles.voip.ms' is now Reachable. (64ms / 2000ms)

Thanks,

 

[mcbsys]

Peer details for losangeles.voip.ms (67.215.241.250):

canreinvite=nonat
nat=yes
context=from-trunk
host=67.215.241.250
secret=secret
type=peer
username=123456
disallow=all
allow=ulaw&g729
fromuser=123456
trustrpid=yes
sendrpid=yes
insecure=invite
qualify=yes

I think 2000ms is the Asterisk default, i.e. that's what you get when qualify=yes.

 

[blanchae]

Interesting that the time that the SIP peer is lagged and then cleared is almost exactly 10 seconds every time... I would check your logs both asterisk and Linux to see what was happening on your server at those times.

 

[mcbsys]

Document on Sip poke noanswer: Peer 'XXX' is now UNREACHABLE! states:

"If qualify=yes or a numeric value, then asterisk will sometimes poke this peer by sending a 'SIP OPTIONS' request to phones or other pbx's."

My hunch is that "sometimes" is defined as 10 seconds, so basically the target is reachable on the next poke.

These messages are from /var/log/asterisk/full and there aren't consistently any other messages at the same times.

I checked /var/log/messages and again, nothing at the time of the lags. Isn't this where network errors would be? I do see UDP and DHCP stuff logged here, nothing about DNS.

I wonder if my gigabit switch isn't being nice to this old 10/100 adapter--I'll try fixing it at 100. However if it's network/DNS issues, I would think I would see problems with internal SIP devices (IP phones) as well...

BIND is not configured, so no local DNS server. DCHP gets DNS servers from the router, and they are correctly stored in /etc/resolv.conf. The first DNS server is an in-house Windows machine, ping time 0.5ms. Second and third DNS servers are from OpenDNS.org. If I am reading this right, the NIC looks to be happy:

/sbin/ifconfig
eth0      Link encap:Ethernet  HWaddr xx:xx:xx:xx:xx:xx
          inet addr:x.x.x.x  Bcast:x.x.x.255  Mask:255.255.255.0
          inet6 addr: xxxx::xxxx:xxxx:xxxx:xxxx/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:397380 errors:0 dropped:0 overruns:0 frame:0
          TX packets:398576 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:100
          RX bytes:69519439 (66.2 MiB)  TX bytes:265960288 (253.6 MiB)
          Base address:0xcce0 Memory:fe820000-fe840000

 

[mcbsys]

Went on site two days ago. Downgraded the switch port from Auto-negotiation to fixed at 100 Mbps Full. Upgraded the cable connecting the switch to the PBX box from a cheap, thin cable to a nice thick Cat6 cable.

Latest log shows no change: 1 registration failure and about 20 "lagged" messages in 24 hours.

Should I be concerned? If you use an ITSP, do you get this many "lagged" messages?

 

[blanchae]

I wonder if it's your router that's causing the problem. Have you some interesting QoS going on? What does pingtest.net show?

 

[mcbsys]

Thanks. Yes, it's a Linksys E3000 running Tomato with QoS enabled. I'll disable QoS for a day and see what happens.

 

[gregc]

If you haven't seen it, this is a great tutorial on Tomato and QOS.

 

[mcbsys]

Thanks, that does look familiar. I don't see how QoS can be the issue since I'm getting these lag messages day and night, even when there should be almost no Internet usage. Also the PBX has Highest Priority so even if there were contention, it should win.

 

[Hyksos]

Why not run a ping test from the pbx and a pc station to losangeles.voip.ms and log all of it to a text file for 24h making sure response of 3000ms would get log and not timeouted.

The same could be done from another ISP, your lab maybe.

Maybe you would see something interesting. no?

 

[mcbsys]

Good suggestion. I set up a program called MultiPing on a Windows machine a couple weeks ago, pinging losangeles.voip.ms and cisco.com. Although there were occasional ping timeouts, they did not occur at the same time as the "lagged" messages from Asterisk. It seemed like the remote server was responding to PING quickly, but was not always processing the Asterisk SIP OPTIONS request fast enough. Like maybe more of a CPU or disk issue on their end than a connection issue.

It would take me awhile to figure out how to do the same thing as MultiPing directly from the PBX box. Another thought was to create a new PiaF install on a different machine, maybe even bypass the router as voip.ms is asking me to do, and see if that makes a difference.

 

[mcbsys]

What does pingtest.net show?

Sorry missed that question before.

With someone else connected remotely to another computer, pingtest.net first test showed B*, 56ms, 12ms jitter, on a 150-mile connection (about right for San Diego to Los Angeles).

After installing Java, other user still logged on, pingtest.net shows quality A, 47ms, 3ms jitter, 0% packet loss.

VisualWare.com VoIP test shows 0ms average jitter, 0% average packet loss, MOS 4.2.

 

[Hyksos]

Of course that can't always be true but I would believe voip.ms in that it's not on their end.

They have the ability to aggragate the information from all their customers. First clue for a provider like them and big indication to you is that if it was something on their side you would not be the only one complaining since you're not alone at their LA pop.

I could setup my piaf with my voip.ms did and move it to LA. Maybe I would get the same even if I doubt it

 

[mcbsys]

Good points, and the customer hasn't even complained, so I don't want to point fingers at voip.ms.

As you can see in my initial post, the "lagged" messages are flagged as NOTICE level although I am logging all the way up to VERBOSE. NOTICE is two steps below VERBOSE according to this page:

http://www.automated.it/asterisk/lah-3-6-05_5.html

 

[blanchae]

Have you checked all the PBX logs for unusual activities? How big are your log files? What does the disk space look like? Is swap being used? What does top report? How about the Tomato logs? Is there some unusual activity going on the network at that particular time? Is the network vlan'd? How are you giving priority to voice traffic? You can only give priority to outgoing traffic. You have no control over incoming.

 

[mcbsys]

First: The "lagged" notices continued after disabling QoS on the router so I've re-enabled it.

blanchae, to answer your questions:

top - 10:56:20 up 3 days, 25 min,  1 user,  load average: 0.02, 0.02, 0.00
Tasks:  95 total,   1 running,  94 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.0%us,  0.3%sy,  0.0%ni, 99.0%id,  0.7%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   1035292k total,   759160k used,   276132k free,   158280k buffers
Swap:   779144k total,        0k used,   779144k free,   456412k cached

I got burned by a runaway log a few years back so I set up monitoring of disk space, CPU usage, and memory. Every five minutes, a process (GFI MAX) on a Windows server checks those three via SNMP. Usually I see CPU usage spike to 65% or so once per day, during the FreePBX backup at 12:30am.

/var/log/messages is growing to a max of 360K before it is rotated once per week, or 116K if there are no reboots. Most of the messages are about tht SNMP connections. Other messages confirm DHCP acquisition, time sync, and log rotation. It all looks normal to me.

I did have an interesting situation about three weeks ago. The server had not been rebooted in months. Disk usage was always 36%. After a reboot, it dropped to 12%. I run a job to delete old backups every day. Maybe it hadn't actually freed up the space. It was during that reboot that I discovered that one of the three disks in the RAID 5 array had failed. That has since been replaced and rebuilt, and RAID monitoring software installed.

Tomato logs: I just checked three times that I had "lagged" messages. There are no messages in the Tomato log at the same times.

The router serves is a DHCP server, and I do have this message fairly often:

daemon.warn dnsmasq-dhcp[776]:  not giving name PBX to the DHCP lease of x.x.x.140 because the name exists in /etc/dnsmasq/hosts/hosts with address x.x.x.145

.140 is the main PBX IP. The .145 address is a Dell DRAC card in the same server. I could probably change its name from "PBX" to something else but could that really cause this issue?

There is a separate VLAN for guest wireless but the PBX and phones are all wired.

As for how I am giving priority to voice traffic, I assume you mean how did I set up QoS Classification in Tomato? I initially did it by ports (5060-5063 and 10000-20000). A few weeks back, I also added the IPs of the PBX server and the IP phones as both source and destination. Those categories and DNS are the only ones with the Highest classification.

Per the QoS article that GregC linked, you can limit inbound traffic as well:

A better solution can be achieved by ALSO using the “incoming” traffic limit in Tomato P2P class to set a limit on incoming P2P data. So how does this work? The connection tracking section of the router firmware keeps a record of all outgoing P2P TCP packets and then attempts to keep a tally on any incoming TCP packets associated with it. It can therefore add them all up and then calculate the speed of the incoming P2P, which can then be limited. So we could, for example, set an incoming limit on our connection of something under 2 Mbps. If this is exceeded, the router will drop packetsitalic text, forcing the sender to back off and resend the data – once again allowing the link to stabilize. Tomato's QOS / Limiter is actually just using the normal method of TCP congestion control to shape traffic of the individual classes.

 

[blanchae]

.daemon.warn dnsmasq-dhcp[776]: not giving name PBX to the DHCP lease of x.x.x.140 because the name exists in /etc/dnsmasq/hosts/hosts with address x.x.x.145

How long is your lease time? I would expect the lagging errors due to DHCP to be very periodical not random like we are seeing. You are not using DHCP (dynamic IPs) for your servers are you? Have you excluded your server IP addresses from the DHCP pool?

 

[mcbsys]

Eugene, the server pulls its IP via DHCP from the router. On the router, I set up the server's MAC address to map to a specific IP, which also reserves it. It looks like Tomato gives leases of about 9.5 hours. I could set that to infinite or custom but as you say, the lag issues are random. Also I haven't seen any errors that DCHP acquisition ever fails.

 

[mcbsys]

I had an old PiaF 1.4 Hyper-V virtual machine so I've restored that on my server and set up losangeles.voip.ms. I won't be using it for calls but at least it should show if I get "lagged" messages on the trunk.

 

[blanchae]

I'm trying to brainstorm and not overlook anything that might be happening at your end. I was thinking that if another device tried to grab the same IP as your server through DHCP then that could cause random problems. That dnsmasq-dhcp[776] warning stills bugs me. I would change the hosts name for .145 to stop the error. So far that's the only thing out of the ordinary.

Personally, I put static IPs on the servers out of the range of the DHCP pool. Don't have to worry about conflicts.