Getting some warnings in logs and the system seems is slower

[rahat651]

We are new to Vicidial and preparing our call solution. With one or two calls at a time the system seems to be slower and bulky. We have noticed the followings in the log file. Not sure if those are causing any issue.

If anyone knows solution to any of the following logs that would be really helpful:

Code: Select all

[Aug 13 00:15:30] ERROR[2011][C-0000010e]: netsock2.c:305 ast_sockaddr_resolve: getaddrinfo("vicibox9", "(null)", ...): Name or service not known
[Aug 13 00:15:30] WARNING[2011][C-0000010e]: acl.c:835 resolve_first: Unable to lookup 'vicibox9'
[Aug 13 00:15:35]   == Using SIP RTP CoS mark 5
[Aug 13 00:15:35]        > 0x7f88bc073080 -- Strict RTP learning after remote address set to: 192.168.150.20:51278
[Aug 13 00:15:35]     -- Executing [901743355733@default:1] AGI("SIP/200-000001c2", "agi://127.0.0.1:4577/call_log") in new stack
[Aug 13 00:15:35]     -- <SIP/200-000001c2>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[Aug 13 00:15:35]     -- Executing [901743355733@default:2] Set("SIP/200-000001c2", "CALLERID(num)=09638024024") in new stack
[Aug 13 00:15:35]     -- Executing [901743355733@default:3] Dial("SIP/200-000001c2", "SIP/DelTa9/01743355733,23,tTor") in new stack
[Aug 13 00:15:46]   == Using SIP RTP CoS mark 5
[Aug 13 00:15:46]     -- Called SIP/DelTa9/01743355733
[Aug 13 00:15:46]   == Spawn extension (default, 901743355733, 3) exited non-zero on 'SIP/200-000001c2'
[Aug 13 00:15:46] WARNING[19770][C-0000010e]: func_hangupcause.c:140 hangupcause_read: Unable to find information for channel
[Aug 13 00:15:46]     -- Executing [h@default:1] AGI("SIP/200-000001c2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0-----CANCEL---------------)") in new stack
[Aug 13 00:15:46]     -- <SIP/200-000001c2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0-----CANCEL---------------) completed, returning 0
[Aug 13 00:15:46]   == Using SIP RTP CoS mark 5


Code: Select all

[Aug 12 23:33:29]     -- Called SIP/200
[Aug 12 23:33:29]     -- SIP/200-000001c0 is ringing
[Aug 12 23:33:33]        > 0x7f88bc097280 -- Strict RTP learning after remote address set to: 192.168.150.20:63140
[Aug 12 23:33:33]     -- SIP/200-000001c0 answered SIP/DelTa9-000001bf
[Aug 12 23:33:33]     -- Channel SIP/200-000001c0 joined 'simple_bridge' basic-bridge <cc7ca07f-6596-4b40-8606-67dec4d7dd26>
[Aug 12 23:33:33]     -- Channel SIP/DelTa9-000001bf joined 'simple_bridge' basic-bridge <cc7ca07f-6596-4b40-8606-67dec4d7dd26>
[Aug 12 23:33:33]        > 0x7f88bc097280 -- Strict RTP qualifying stream type: audio
[Aug 12 23:33:33]        > 0x7f88bc097280 -- Strict RTP switching source address to 118.67.223.126:41771
[Aug 12 23:33:34] WARNING[14774][C-0000010c]: file.c:259 ast_writestream: Translated frame write failed
[Aug 12 23:33:34] WARNING[14774][C-0000010c]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 12 23:33:34] WARNING[14774][C-0000010c]: file.c:259 ast_writestream: Translated frame write failed
[Aug 12 23:33:34] WARNING[14774][C-0000010c]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 12 23:33:34] WARNING[14774][C-0000010c]: file.c:259 ast_writestream: Translated frame write failed
[Aug 12 23:33:34] WARNING[14774][C-0000010c]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 12 23:33:34] WARNING[14774][C-0000010c]: file.c:259 ast_writestream: Translated frame write failed
[Aug 12 23:33:34] WARNING[14774][C-0000010c]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 12 23:33:34] WARNING[14774][C-0000010c]: file.c:259 ast_writestream: Translated frame write failed
[Aug 12 23:33:34] WARNING[14774][C-0000010c]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 12 23:33:34] WARNING[14774][C-0000010c]: file.c:259 ast_writestream: Translated frame write failed
[Aug 12 23:33:34] WARNING[14774][C-0000010c]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 12 23:33:34] WARNING[14774][C-0000010c]: file.c:259 ast_writestream: Translated frame write failed
[Aug 12 23:33:34] WARNING[14774][C-0000010c]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 12 23:33:38]        > 0x7f88bc097280 -- Strict RTP learning complete - Locking on source address 118.67.223.126:41771
[Aug 12 23:33:38]        > 0x7f88bc097280 -- Strict RTP learning after remote address set to: 192.168.150.20:63140
[Aug 12 23:33:38]     -- Started music on hold, class 'default', on channel 'SIP/DelTa9-000001bf'
[Aug 12 23:33:39]     -- Stopped music on hold on SIP/DelTa9-000001bf
[Aug 12 23:33:39]     -- Channel SIP/DelTa9-000001bf left 'simple_bridge' basic-bridge <cc7ca07f-6596-4b40-8606-67dec4d7dd26>

Code: Select all

[Aug 12 23:46:10] NOTICE[2011]: chan_sip.c:24672 handle_response_peerpoke: Peer 'DelTa9' is now Lagged. (3305ms / 2000ms)
[Aug 12 23:46:20] NOTICE[2011]: chan_sip.c:24672 handle_response_peerpoke: Peer 'DelTa9' is now Reachable. (20ms / 2000ms)

Code: Select all

[Aug 13 00:06:01]   == Manager 'sendcron' logged off from 127.0.0.1
[Aug 13 00:06:02]   == Manager 'sendcron' logged off from 127.0.0.1
[Aug 13 00:06:06]   == Manager 'sendcron' logged on from 127.0.0.1
[Aug 13 00:06:06]   == Manager 'sendcron' logged off from 127.0.0.1
[Aug 13 00:07:02]   == Manager 'sendcron' logged on from 127.0.0.1
[Aug 13 00:07:02]   == Manager 'sendcron' logged on from 127.0.0.1
[Aug 13 00:07:02]   == Manager 'sendcron' logged off from 127.0.0.1
[Aug 13 00:07:02]   == Manager 'sendcron' logged off from 127.0.0.1
[Aug 13 00:07:07]   == Manager 'sendcron' logged on from 127.0.0.1
[Aug 13 00:07:07]   == Manager 'sendcron' logged off from 127.0.0.1
[Aug 13 00:08:01]   == Manager 'sendcron' logged on from 127.0.0.1
[Aug 13 00:08:01]   == Manager 'sendcron' logged off from 127.0.0.1
[Aug 13 00:08:01]   == Manager 'sendcron' logged on from 127.0.0.1
[Aug 13 00:08:02]   == Manager 'sendcron' logged off from 127.0.0.1

[williamconley]

1) Vicibox versions have a pattern like "9.X.X". 2.14xxx is the Vicidial version. Vicidial is the dialer software, ViciBOX is the installer for Vicidial. So posting your correct Vicibox version would be useful.

2) "slower and bulkier" is rather vague. Is dialing not keeping up with the expected call count based on available agents? Or does it take 15 minutes to boot? or is audio delayed during calls? You can say it in English without techtalk, but it's much more useful if you describe in detail what you are experiencing. Without that we have very little hope of identifying, much less helping you resolve, your issue(s).

3) getaddrinfo("vicibox9"...: somewhere in your system it believes that it's FQDN is vicibox9 instead of an IP or domain name. It then attempts to get an IP for vicibox9 and fails because it's not been provided with a TLD default to check for partial domain names. For instance, when I search for "mail" on a properly configured server at my office, the server will Assume ".poundteam.com" belongs at the end of that, and it will check DNS for "mail.poundteam.com". But your system is not set up to check for "vicibox9.xxxx.xxxx". Find that entry in asterisk or the OS and modify it to a fully qualified domain name or an IP to remove that error.

4) Are you implying that the server in question "used to work faster"? In what way in what screen or how do you know?

5) ast_write: Failed to write data to channel monitor write stream: Are you out of HD space on the drive storing recordings or in the /var/spool/asterisk/monitor folder? (df -h)

6) DelTa9' is now Lagged. (3305ms / 2000ms): Your server sends "qualify" packets to all sip accounts to validate them if configured to do so. Usually something like "qualify=xxxx" in admin->carriers account entry. The packet to DelTa9 took 3305ms to return which is more than the configured "acceptable" timeframe of 2000ms. Either change to qualify=3500 or qualify=no or ... fix the network connection to that sip account.

Qualify is primarily meant as a "cutoff switch" for poorly connected sip servers whose network connection is no longer acceptable (defined as a lag time over "qualify=xxxx" ms). But that's meant to fail the sip account in question and allow for failover, and if you don't have failover configured it can actually be counterproductive to use. On the other hand, while it will fail on occasion it may actually notify you that you have a networking problem. So the headache may help you fix a problem. Most end-users, however, prefer to just allow the connection unless call qualify is affected ... and this is usually something you'll be informed of by the agents on the calls. Which beats random "hey, that trunk doesn't work ... no, wait, now it does!" for most call centers. Especially since you may never even know it's happening unless you happen to look at this log.

7) Manager 'sendcron' logged on from 127.0.0.1: That's normal. Which is why it's not an ERROR or a WARNING or even a NOTICE. It's just part of the normal operating (in this case idle) activity of the server. When the server is in operation, it will have other traffic, but when it's idle the sendcron script checks in regularly and this is logged and with no other activity is quite visible.

8 ) You've posted excellent specs for your system (with the notable exception of listing the Vicidial version where the Vicibox version should be). It should be noticed however that "Core i3" means ... nothing. Post the model number of the CPU or at least the number of cores (and threads if you have hyperthreading on).

9) If the system is getting old, consider archiving your logs. There is a script for this in crontab -e which handles the database log tables in various stages. It's also a good idea to use various utilities to manage all the logs in /var/log (and sub folders) so they do not fill up the HD. "logrotater" is nice.

[rahat651]

Thanks william for the detail reply.

1) Vicibox versions have a pattern like "9.X.X". 2.14xxx is the Vicidial version. Vicidial is the dialer software, ViciBOX is the installer for Vicidial. So posting your correct Vicibox version would be useful.

It is 9.0.2

2) "slower and bulkier" is rather vague. Is dialing not keeping up with the expected call count based on available agents? Or does it take 15 minutes to boot? or is audio delayed during calls? You can say it in English without techtalk, but it's much more useful if you describe in detail what you are experiencing. Without that we have very little hope of identifying, much less helping you resolve, your issue(s).

This is the first time we have prepared a solution based on Vicidial. On an older server we have only Asterisk 15 on CLI running. No interface or database.
From the same location we have tested with the same test remote agents.

On the new system when there are three/four remote agents available and a single call comes in then we have noticed the followings:
- If we repetitively call the system then at random the system take 2/3 seconds to play the welcome audio which is the first thing a caller hears. As if the system hangs for 2/3 seconds.
Never happens with the old system.
- Most of the time Incoming call from IVR to to SIP phone takes few seconds longer than the previous system
-When a SIP operator forwards the call to another group where we have some remote agents in queue, the call switching to remote agents always takes couple of seconds longer than the older system. Older system also has got agent queue with the same remote agent numbers.
- Some time on the remote agent side it rings for couple of seconds (not as expected) and then starts to ring another number as the previous agent could not receive the call. Where as we have on-hook time set to 23 seconds. But some time it ratings around 15/16 seconds which is ok.

3) getaddrinfo("vicibox9"...: somewhere in your system it believes that it's FQDN is vicibox9 instead of an IP or domain name. It then attempts to get an IP for vicibox9 and fails because it's not been provided with a TLD default to check for partial domain names. For instance, when I search for "mail" on a properly configured server at my office, the server will Assume ".poundteam.com" belongs at the end of that, and it will check DNS for "mail.poundteam.com". But your system is not set up to check for "vicibox9.xxxx.xxxx". Find that entry in asterisk or the OS and modify it to a fully qualified domain name or an IP to remove that error.

Got your point. Thanks. If you could point me to how to do that would be great as I am new to the systems and Linux too.

Code: Select all

4) Are you implying that the server in question "used to work faster"? In what way in what screen or how do you know?

Same as point#2. Its a new system but with the same data the processing take few seconds more when compared to the older system.

5) ast_write: Failed to write data to channel monitor write stream: Are you out of HD space on the drive storing recordings or in the /var/spool/asterisk/monitor folder? (df -h)

I have checked. only 1% is used. There is enough space.

Code: Select all

tmpfs           6.0G  5.6M  6.0G   1% /var/spool/asterisk/monitor

6) DelTa9' is now Lagged. (3305ms / 2000ms): Your server sends "qualify" packets to all sip accounts to validate them if configured to do so. Usually something like "qualify=xxxx" in admin->carriers account entry. The packet to DelTa9 took 3305ms to return which is more than the configured "acceptable" timeframe of 2000ms. Either change to qualify=3500 or qualify=no or ... fix the network connection to that sip account.

Qualify is primarily meant as a "cutoff switch" for poorly connected sip servers whose network connection is no longer acceptable (defined as a lag time over "qualify=xxxx" ms). But that's meant to fail the sip account in question and allow for failover, and if you don't have failover configured it can actually be counterproductive to use. On the other hand, while it will fail on occasion it may actually notify you that you have a networking problem. So the headache may help you fix a problem. Most end-users, however, prefer to just allow the connection unless call qualify is affected ... and this is usually something you'll be informed of by the agents on the calls. Which beats random "hey, that trunk doesn't work ... no, wait, now it does!" for most call centers. Especially since you may never even know it's happening unless you happen to look at this log.

Will discuss with the IPTSP provider.

8 ) You've posted excellent specs for your system (with the notable exception of listing the Vicidial version where the Vicibox version should be). It should be noticed however that "Core i3" means ... nothing. Post the model number of the CPU or at least the number of cores (and threads if you have hyperthreading on).

I have updated the spec.

9) If the system is getting old, consider archiving your logs. There is a script for this in crontab -e which handles the database log tables in various stages. It's also a good idea to use various utilities to manage all the logs in /var/log (and sub folders) so they do not fill up the HD. "logrotater" is nice.

It is a new system not even a month older. But its an excellent point to be noted for the future.

[carpenox]

check your /etc/hosts file to see if vicibox9 is listed there.

Is this a virtual server with those specs or dedicated box?

[rahat651]

It is a virtual server.
In the hosts file there are few entries like:
127.0.0.1 localhost

But nothing like Vicibox9. Should I add "127.0.0.1 vicibox9"?

[carpenox]

yes u should

[rahat651]

Ok. I have added the "127.0.0.1 vicibox9" entry to the host file.

There is enough space on the disk.

Code: Select all

tmpfs           6.0G  5.6M  6.0G   1% /var/spool/asterisk/monitor

Any idea on the following logs. I think those also creates load on the server too:

Code: Select all

[Aug 20 17:01:40] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:01:40] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:01:40] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:01:40] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:01:40] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:01:40] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:01:40] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:01:40] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:01:40] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:01:40] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:01:40] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:01:40] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:01:40] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:01:40] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:01:40] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:01:40] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:01:41] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:01:41] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:01:45]        > 0x7f6110057370 -- Strict RTP learning complete - Locking on source address 117.66.223.127:34343
[Aug 20 17:01:56] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:01:56] WARNING[13483][C-000002c7]: channel.c:4335 __ast_read: Failed to write data to channel monitor read stream
[Aug 20 17:02:01] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:02:01] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:02:01] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:02:01] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:02:01]   == Manager 'sendcron' logged on from 127.0.0.1
[Aug 20 17:02:01]   == Manager 'sendcron' logged on from 127.0.0.1
[Aug 20 17:02:01]   == Manager 'sendcron' logged off from 127.0.0.1
[Aug 20 17:02:02]   == Manager 'sendcron' logged off from 127.0.0.1
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:02:06] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:02:06]   == Manager 'sendcron' logged on from 127.0.0.1
[Aug 20 17:02:06]   == Manager 'sendcron' logged off from 127.0.0.1
[Aug 20 17:02:09] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:02:09] WARNING[13483][C-000002c7]: channel.c:4335 __ast_read: Failed to write data to channel monitor read stream
[Aug 20 17:02:16] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:02:16] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:02:16] WARNING[13483][C-000002c7]: file.c:259 ast_writestream: Translated frame write failed
[Aug 20 17:02:16] WARNING[13483][C-000002c7]: channel.c:5478 ast_write: Failed to write data to channel monitor write stream
[Aug 20 17:02:40]        > 0x7f6110057370 -- Strict RTP learning after remote address set to: 192.168.150.28:60726

[carpenox]

that is typically from a hard drive space issue.....but you said its a new system. what do you see when you type "df -h"

[rahat651]

Code: Select all

vicibox9:/etc/asterisk # df -kh
Filesystem      Size  Used Avail Use% Mounted on
devtmpfs        7.9G     0  7.9G   0% /dev
tmpfs           7.9G     0  7.9G   0% /dev/shm
tmpfs           7.9G  737M  7.2G  10% /run
tmpfs           7.9G     0  7.9G   0% /sys/fs/cgroup
/dev/vda4       193G  7.7G  176G   5% /
tmpfs           6.0G     0  6.0G   0% /var/spool/asterisk/monitor
/dev/vda2        20M  1.1M   19M   6% /boot/efi
tmpfs           1.6G     0  1.6G   0% /run/user/0