Hi, I am looking for help tracking down the root cause of why our freepbx server starts behaving wierd, and then quits processing calls until I reload freepbx and asterisk via SSH.
On 3/28 I had an issue where at first, each incoming call would show up on our phones as 2-4 incoming calls at the same time. After about 5 to 10 minutes, we were no longer able to be called. I would get busy signal if I tried dialing our office from my cell phone. At this point, I restarted freepbx and asterisk in command line. Calls started working, but were extremely delayed. I decided to reboot the machine and this restored normal services.
This morning 4/2, outbound calls quit working. So did inbound. I dialed a coworker’s extension and there was dead air, 15 seconds later his phone started ringing from when I had tried earlier. I went ahead and rebooted the whole server instead of troubleshooting further.
Investigation:
No big red flags in /var/log/asterisk/full.
Other than proof of the very delayed phone call this morning:
[2019-04-02 08:04:54] VERBOSE[21824][C-00000068] app_stack.c: PJSIP/522-00000188 Internal Gosub(func-apply-sipheaders,s,1) start
[2019-04-02 08:04:54] VERBOSE[21824][C-00000068] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp(“PJSIP/522-00000188”, “Applying SIP Headers to channel PJSIP/522-00000188”) in new stack
[2019-04-02 08:04:54] VERBOSE[21824][C-00000068] pbx.c: Executing [s@func-apply-sipheaders:2] Set(“PJSIP/522-00000188”, “TECH=PJSIP”) in new stack
[2019-04-02 08:04:54] VERBOSE[21824][C-00000068] pbx.c: Executing [s@func-apply-sipheaders:3] Set(“PJSIP/522-00000188”, “SIPHEADERKEYS=”) in new stack
[2019-04-02 08:04:54] VERBOSE[21824][C-00000068] pbx.c: Executing [s@func-apply-sipheaders:4] While(“PJSIP/522-00000188”, “0”) in new stack
[2019-04-02 08:04:54] VERBOSE[21824][C-00000068] app_while.c: Jumping to priority 11
[2019-04-02 08:04:54] VERBOSE[21824][C-00000068] pbx.c: Executing [s@func-apply-sipheaders:12] Return(“PJSIP/522-00000188”, “”) in new stack
[2019-04-02 08:04:54] VERBOSE[21824][C-00000068] app_stack.c: Spawn extension (from-internal, 522, 1) exited non-zero on ‘PJSIP/522-00000188’
[2019-04-02 08:04:54] VERBOSE[21824][C-00000068] app_stack.c: PJSIP/522-00000188 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2019-04-02 08:04:54] VERBOSE[21824][C-00000068] app_dial.c: Called PJSIP/522/sip:[email protected]:5060
[2019-04-02 08:04:54] VERBOSE[22303] netsock2.c: Using SIP RTP Audio TOS bits 184
[2019-04-02 08:04:54] VERBOSE[22303] netsock2.c: Using SIP RTP Audio TOS bits 184 in TCLASS field.
[2019-04-02 08:04:54] VERBOSE[22303] netsock2.c: Using SIP RTP Audio CoS mark 5
[2019-04-02 08:04:54] VERBOSE[21824][C-00000068] app_dial.c: Connected line update to PJSIP/521-00000187 prevented.
[2019-04-02 08:05:08] VERBOSE[21824][C-00000068] app_dial.c: PJSIP/522-00000188 is ringing
[2019-04-02 08:05:08] VERBOSE[21824][C-00000068] app_dial.c: PJSIP/522-00000188 is ringing
[2019-04-02 08:05:08] VERBOSE[21824][C-00000068] app_macro.c: Spawn extension (macro-dial-one, s, 54) exited non-zero on ‘PJSIP/521-00000187’ in macro ‘dial-one’
[2019-04-02 08:05:08] VERBOSE[21824][C-00000068] app_macro.c: Spawn extension (macro-exten-vm, s, 26) exited non-zero on ‘PJSIP/521-00000187’ in macro ‘exten-vm’
[2019-04-02 08:05:08] VERBOSE[21824][C-00000068] pbx.c: Spawn extension (ext-local, 522, 2) exited non-zero on ‘PJSIP/521-00000187’
[2019-04-02 08:05:08] VERBOSE[21824][C-00000068] pbx.c: Executing [h@ext-local:1] Macro(“PJSIP/521-00000187”, “hangupcall,”) in new stack
[2019-04-02 08:05:08] VERBOSE[21824][C-00000068] pbx.c: Executing [s@macro-hangupcall:1] GotoIf(“PJSIP/521-00000187”, “1?theend”) in new stack
[2019-04-02 08:05:08] VERBOSE[21824][C-00000068] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2019-04-02 08:05:08] VERBOSE[21824][C-00000068] pbx.c: Executing [s@macro-hangupcall:3] ExecIf(“PJSIP/521-00000187”, “0?Set(CDR(recordingfile)=)”) in new stack
[2019-04-02 08:05:08] VERBOSE[21824][C-00000068] pbx.c: Executing [s@macro-hangupcall:4] NoOp(“PJSIP/521-00000187”, "PJSIP/522-00000188 monior file= ") in new stack
[2019-04-02 08:05:08] VERBOSE[21824][C-00000068] pbx.c: Executing [s@macro-hangupcall:5] AGI(“PJSIP/521-00000187”, “attendedtransfer-rec-restart.php,PJSIP/522-00000188,”) in new stack
[2019-04-02 08:05:09] VERBOSE[21824][C-00000068] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/attendedtransfer-rec-restart.php
[2019-04-02 08:05:12] VERBOSE[21824][C-00000068] res_agi.c: <PJSIP/521-00000187>AGI Script attendedtransfer-rec-restart.php completed, returning 0
[2019-04-02 08:05:12] VERBOSE[21824][C-00000068] pbx.c: Executing [s@macro-hangupcall:6] Hangup(“PJSIP/521-00000187”, “”) in new stack
[2019-04-02 08:05:12] VERBOSE[21824][C-00000068] app_macro.c: Spawn extension (macro-hangupcall, s, 6) exited non-zero on ‘PJSIP/521-00000187’ in macro ‘hangupcall’
[2019-04-02 08:05:12] VERBOSE[21824][C-00000068] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on ‘PJSIP/521-00000187’
In freepbx log, I see something about “Connection attempt to AMI failed”
There are errors about AMI failing on 3/28 during the last call failure issues as well.
[2019-Apr-02 08:05:32] [WARNING] (libraries/modulefunctions.legacy.php:7) - Depreciated Function module_getinfo detected in /var/www/html/admin/modules/bulkhandler/Console/Bulkimport.class.php on line 10
[2019-Apr-02 08:05:34] [WARNING] (libraries/modulefunctions.legacy.php:7) - Depreciated Function module_getinfo detected in /var/www/html/admin/modules/cxpanel/functions.inc.php on line 67
[2019-Apr-02 08:05:34] [WARNING] (libraries/modulefunctions.legacy.php:7) - Depreciated Function module_getinfo detected in /var/www/html/admin/modules/cxpanel/functions.inc.php on line 76
[2019-Apr-02 08:05:34] [WARNING] (libraries/modulefunctions.legacy.php:7) - Depreciated Function module_getinfo detected in /var/www/html/admin/modules/bulkhandler/Console/Bulkimport.class.php on line 10
[2019-Apr-02 08:05:47] [FATAL] (BMO/GPG.class.php:476) - GPG command took too long to run. Command was ‘/usr/bin/gpg2 --homedir /home/asterisk/.gnupg --no-permission-warning --keyserver-options auto-key-retrieve=true,timeout=10 --no-tty --status-fd 3 --keyserver pool.sks-keyservers.(Broke to post)net --refresh-keys’
[2019-Apr-02 08:05:47] [ERROR] (BMO/GPG.class.php:575) - Tried to refresh keys and failed with: GPG took too long to run the command: [/usr/bin/gpg2 --homedir /home/asterisk/.gnupg --no-permission-warning --keyserver-options auto-key-retrieve=true,timeout=10 --no-tty --status-fd 3 --keyserver pool.sks-keyservers(broke on purpse) net --refresh-keys]
[2019-Apr-02 08:05:51] [WARNING] (BMO/Cache.class.php:235) - Redis enabled but not running, falling back to filesystem [Redis server went away]
[2019-Apr-02 08:05:51] [WARNING] (BMO/Cache.class.php:235) - Redis enabled but not running, falling back to filesystem [Redis server went away]
[2019-Apr-02 08:05:51] [WARNING] (BMO/Cache.class.php:235) - Redis enabled but not running, falling back to filesystem [Redis server went away]
[2019-Apr-02 08:05:52] [WARNING] (libraries/modulefunctions.legacy.php:7) - Depreciated Function module_getinfo detected in /var/www/html/admin/modules/cxpanel/functions.inc.php on line 67
[2019-Apr-02 08:05:52] [WARNING] (libraries/modulefunctions.legacy.php:7) - Depreciated Function module_getinfo detected in /var/www/html/admin/modules/cxpanel/functions.inc.php on line 76
[2019-Apr-02 08:05:52] [WARNING] (BMO/Cache.class.php:235) - Redis enabled but not running, falling back to filesystem [Redis server went away]
[2019-Apr-02 08:05:52] [WARNING] (libraries/modulefunctions.legacy.php:7) - Depreciated Function module_getinfo detected in /var/www/html/admin/modules/bulkhandler/Console/Bulkimport.class.php on line 10
[2019-Apr-02 08:05:53] [WARNING] (BMO/Cache.class.php:235) - Redis enabled but not running, falling back to filesystem [Redis server went away]
[2019-Apr-02 08:05:53] [WARNING] (BMO/Cache.class.php:235) - Redis enabled but not running, falling back to filesystem [Redis server went away]
[2019-Apr-02 08:05:54] [WARNING] (BMO/Cache.class.php:235) - Redis enabled but not running, falling back to filesystem [Redis server went away]
[2019-Apr-02 08:05:55] [WARNING] (BMO/Cache.class.php:235) - Redis enabled but not running, falling back to filesystem [Redis server went away]
[2019-Apr-02 08:05:55] [WARNING] (BMO/Cache.class.php:235) - Redis enabled but not running, falling back to filesystem [Redis server went away]
[2019-Apr-02 08:05:56] [WARNING] (BMO/Cache.class.php:235) - Redis enabled but not running, falling back to filesystem [Redis server went away]
[2019-Apr-02 08:05:56] [WARNING] (BMO/Cache.class.php:235) - Redis enabled but not running, falling back to filesystem [Redis server went away]
[2019-Apr-02 08:05:57] [WARNING] (BMO/Cache.class.php:235) - Redis enabled but not running, falling back to filesystem [Redis server went away]
[2019-Apr-02 08:05:58] [WARNING] (BMO/Cache.class.php:235) - Redis enabled but not running, falling back to filesystem [Redis server went away]
[2019-Apr-02 08:05:58] [WARNING] (BMO/Cache.class.php:235) - Redis enabled but not running, falling back to filesystem [Redis server went away]
[2019-Apr-02 08:05:59] [CRITICAL] (admin/bootstrap.php:260) - Connection attmempt to AMI failed
[2019-Apr-02 08:05:59] [WARNING] (BMO/Cache.class.php:235) - Redis enabled but not running, falling back to filesystem [Redis server went away]
[2019-Apr-02 08:05:59] [CRITICAL] (admin/bootstrap.php:260) - Connection attmempt to AMI failed
[2019-Apr-02 08:05:59] [WARNING] (BMO/Cache.class.php:235) - Redis enabled but not running, falling back to filesystem [Redis server went away]
[2019-Apr-02 08:06:00] [CRITICAL] (admin/bootstrap.php:260) - Connection attmempt to AMI failed
[2019-Apr-02 08:06:00] [WARNING] (BMO/Cache.class.php:235) - Redis enabled but not running, falling back to filesystem [Redis server went away]
[2019-Apr-02 08:06:01] [CRITICAL] (admin/bootstrap.php:260) - Connection attmempt to AMI failed
I can look more in logs, if anyone has some ideas for me. Any help would be appreciated before this happens to us again!