Phpagi get_variable and set_variable issue on Asterisk 18

Asterisk Asterisk APIs
1

Hi everyone!

So I have just replicated a new environment with Asterisk 18.22, php 8.2 and synced the phpagi-asmanager (version 1.10) fom my running production environment on Asterisk 1.8.9 and php 5.5.3.

The entire PBX setup is running on agi.php from extensions, to queues, to call groups to dialplans etc and is working like a charm.

After replicating on Asterisk 18, I tried to run the same dialplan (extensions.conf) but my call fails; logs pasted below (agi debug is on):

 agi set debug on
AGI Debugging Enabled
  == Using SIP VIDEO CoS mark 6
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
[Jun 19 16:16:44] ERROR[1436]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/1*7403-00000003
[Jun 19 16:16:44] ERROR[1436]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/1*7403-00000003
[Jun 19 16:16:44] ERROR[1436]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/1*7403-00000003
    -- Executing [7405@default:1] AGI("SIP/1*7403-00000003", "agi.php") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/agi.php
<SIP/1*7403-00000003>AGI Tx >> agi_request: agi.php
<SIP/1*7403-00000003>AGI Tx >> agi_channel: SIP/1*7403-00000003
<SIP/1*7403-00000003>AGI Tx >> agi_language: en
<SIP/1*7403-00000003>AGI Tx >> agi_type: SIP
<SIP/1*7403-00000003>AGI Tx >> agi_uniqueid: ehtestvm-1718799404.3
<SIP/1*7403-00000003>AGI Tx >> agi_version: 18.22.0
<SIP/1*7403-00000003>AGI Tx >> agi_callerid: 7403
<SIP/1*7403-00000003>AGI Tx >> agi_calleridname: 7403
<SIP/1*7403-00000003>AGI Tx >> agi_callingpres: 0
<SIP/1*7403-00000003>AGI Tx >> agi_callingani2: 0
<SIP/1*7403-00000003>AGI Tx >> agi_callington: 0
<SIP/1*7403-00000003>AGI Tx >> agi_callingtns: 0
<SIP/1*7403-00000003>AGI Tx >> agi_dnid: 7405
<SIP/1*7403-00000003>AGI Tx >> agi_rdnis: unknown
<SIP/1*7403-00000003>AGI Tx >> agi_context: default
<SIP/1*7403-00000003>AGI Tx >> agi_extension: 7405
<SIP/1*7403-00000003>AGI Tx >> agi_priority: 1
<SIP/1*7403-00000003>AGI Tx >> agi_enhanced: 0.0
<SIP/1*7403-00000003>AGI Tx >> agi_accountcode: 5577864113
<SIP/1*7403-00000003>AGI Tx >> agi_threadid: 140018927584960
<SIP/1*7403-00000003>AGI Tx >>
<SIP/1*7403-00000003>AGI Rx << Starting AGI script
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << AGI object created
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << Inside PBX constructor
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << Inside get agi request
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << before caller id
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << after caller id
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << thi is after caller id set unknown
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << this is before isolate cid
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << inside isolate cid functio
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << this is after isolate cid
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << this is before  get cdr cid
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << this is after get cdr cid
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
    -- <SIP/1*7403-00000003>AGI Script agi.php completed, returning 0
    -- Auto fallthrough, channel 'SIP/1*7403-00000003' status is 'UNKNOWN'
    -- Executing [h@default:1] AGI("SIP/1*7403-00000003", "agi.php,CDR") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/agi.php
<SIP/1*7403-00000003>AGI Tx >> agi_request: agi.php
<SIP/1*7403-00000003>AGI Tx >> agi_channel: SIP/1*7403-00000003
<SIP/1*7403-00000003>AGI Tx >> agi_language: en
<SIP/1*7403-00000003>AGI Tx >> agi_type: SIP
<SIP/1*7403-00000003>AGI Tx >> agi_uniqueid: ehtestvm-1718799404.3
<SIP/1*7403-00000003>AGI Tx >> agi_version: 18.22.0
<SIP/1*7403-00000003>AGI Tx >> agi_callerid: 7403
<SIP/1*7403-00000003>AGI Tx >> agi_calleridname: 7403
<SIP/1*7403-00000003>AGI Tx >> agi_callingpres: 0
<SIP/1*7403-00000003>AGI Tx >> agi_callingani2: 0
<SIP/1*7403-00000003>AGI Tx >> agi_callington: 0
<SIP/1*7403-00000003>AGI Tx >> agi_callingtns: 0
<SIP/1*7403-00000003>AGI Tx >> agi_dnid: 7405
<SIP/1*7403-00000003>AGI Tx >> agi_rdnis: unknown
<SIP/1*7403-00000003>AGI Tx >> agi_context: default
<SIP/1*7403-00000003>AGI Tx >> agi_extension: h
<SIP/1*7403-00000003>AGI Tx >> agi_priority: 1
<SIP/1*7403-00000003>AGI Tx >> agi_enhanced: 0.0
<SIP/1*7403-00000003>AGI Tx >> agi_accountcode: 5577864113
<SIP/1*7403-00000003>AGI Tx >> agi_threadid: 140018927584960
<SIP/1*7403-00000003>AGI Tx >> agi_arg_1: CDR
<SIP/1*7403-00000003>AGI Tx >>
<SIP/1*7403-00000003>AGI Rx << Starting AGI script
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << AGI object created
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << Inside PBX constructor
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << Inside get agi request
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << before caller id
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << after caller id
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << thi is after caller id set unknown
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << this is before isolate cid
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << inside isolate cid function
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << this is after isolate cid
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << this is before  get cdr cid
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000003>AGI Rx << this is after get cdr cid
<SIP/1*7403-00000003>AGI Tx >> 510 Invalid or unknown command
    -- <SIP/1*7403-00000003>AGI Script agi.php completed, returning 0

What i have understood is, phpagi is not catering to get_variables and set_variables in the subclass files of agi.php like config and pbx class files etc…as soon as I comment them out, the echo command underneath is executed ( as seen in AGI Rx above). Reference code snippet pasted below:

  function get_agi_request_parameter($agi) {
        echo "Inside get agi request\n";
        $this->request = $agi->request['agi_request'];
        $this->channel = $agi->request['agi_channel'];
        $this->type = $agi->request['agi_type']; 
        $this->uniqueid = $agi->request['agi_uniqueid'];
        $this->callerid = $agi->request['agi_callerid'];
         #echo  "Inside caller ID request\n";

        if ($this->callerid == '') {
        echo  "before caller id\n";
          # $agi->set_callerid('Unknown');
            echo  "after caller id\n";

            $this->callerid = 'Unknown';
            echo "this is after caller id set unknown is skipped\n";
        }
        $this->calleridname = $agi->request['agi_calleridname'];
        $this->dnid = $agi->request['agi_dnid'];
        $this->context = $agi->request['agi_context'];
        $this->did = $this->extension = $agi->request['agi_extension'];
        $this->accountcode = $agi->request['agi_accountcode'];

        echo "this is before isolate cid\n";

        //Call function to find the cid number
        $this->isolate_cid();
        echo "this is after isolate cid\n";

        echo "this is before  get cdr cid\n";

        #$clid = $agi->get_variable("CDR(clid)");
        echo "this is after get cdr cid\n";


        $clid = $clid['data'];
        if(DEBUGF){
			$this->debug_logfile(INFO, $agi, __FILE__, __LINE__, ' get_agi_request_parameter  CallerID -> ' . $this->callerid . ' ; Channnel-> ' . $this->channel . ' ; UniqueID-> ' . $this->uniqueid . ' ; Accountcode-> ' . $this->accountcode . ' ;Dnid-> ' . $this->dnid . ' ;Type->' . $this->type . ' ; Extension->' . $this->extension);
          
            echo "this is checking the log file\n";
        }
}

Can someone guide me whether I need to install a newer phpagi file from this link (or somewhere else??) or the current version of phpagi is not the causing this issue? Is the Asterisk version 18 an issue? Is php 8 an issue? Is phpagi an issue?
If not, can someone point me in the right direction as to what needs to be done?

Please do not hesitate to ask for more details in case I missed out on something important…

I appreciate your time to read and go through this lenghty post :slight_smile:
Any sort of help will be of great help.

Best,
Hisham

2

I can almost certainly say it is not Asterisk, and is your AGI or the library.

3

Hi @jcolp
if its the agi, then i suppose it shouldn’t be working elsewhere either, no? Because the dialplan, the libraries, the agi is a clone of what is working on my odler asterisk 1.8.9

For reference, this is the upgrade that I did:
centos 5.x → debain 12
asterisk 1.8.9 → asterisk 18.9
php 5.3.3 → php 8.2
mysql 5.0 → mysql 10.11

The same agi is working fine to fetch realtime sip users from the custom pbx GUI.
Status is as follows:

ehtestvm*CLI> sip show peers
Name/username             Host                                    Dyn Forcerport Comedia    ACL Port     Status      Description                      Realtime
1*7403/1*7403             10.10.7.84                               D  Yes        Yes            5060     OK (5 ms)                                    Cached RT
1*7405/1*7405             10.10.7.36                               D  Yes        Yes            5060     OK (5 ms)                                    Cached RT
1*7999/1*7999             10.10.7.20                               D  Yes        Yes            51085    OK (5 ms)                                    Cached RT

Anything else that i can provide you with?

Best,
Hisham

4

Not necessarily, you’ve majorly changed the PHP version which can have underlying behavior changes. I don’t do PHP so I can’t comment on that. I can say from an Asterisk AGI perspective I’m not aware of any issues, and there hasn’t been any breaking changes for a long long long time.

5

Do you belive this could be a hint?

6

If you are trying to use the CDR dialplan function, yes.

7

What is the contents of cdr.conf and full dialplan execution?

8

Also,
the asterisk agi connects with the custom-made GUi for real time data, the files in /var/www/html were also broken due to PHP version change, but i managed to fix all of those issues. Issues were like mysql → mysqli/PDO, curly baces no longer being supported insteak () or for arrays etc.

I know PHP causesd alot of issues from 5.5 to 8 but I am unable to get anything from agi debug on…
I just need a hint to get going becuase if I am able to solve php issues on my GUI, then aserisk ones should be a no brainer

9

Full dialplan execution;

[Jun 19 17:29:40] WARNING[1462][C-00000006]: sip/config_parser.c:818 sip_parse_nat_option: nat=yes is deprecated, use nat=force_rport,comedia instead
[Jun 19 17:29:40] WARNING[1462][C-00000006]: sip/config_parser.c:818 sip_parse_nat_option: nat=yes is deprecated, use nat=force_rport,comedia instead
[Jun 19 17:29:40] WARNING[1462][C-00000006]: sip/config_parser.c:818 sip_parse_nat_option: nat=yes is deprecated, use nat=force_rport,comedia instead
[Jun 19 17:29:40] WARNING[1462][C-00000006]: sip/config_parser.c:818 sip_parse_nat_option: nat=yes is deprecated, use nat=force_rport,comedia instead
[Jun 19 17:29:40] WARNING[1462][C-00000006]: sip/config_parser.c:818 sip_parse_nat_option: nat=yes is deprecated, use nat=force_rport,comedia instead
[Jun 19 17:29:40] WARNING[1462][C-00000006]: sip/config_parser.c:818 sip_parse_nat_option: nat=yes is deprecated, use nat=force_rport,comedia instead
  == Using SIP VIDEO CoS mark 6
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
[Jun 19 17:29:40] ERROR[1436]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/1*7403-00000005
[Jun 19 17:29:40] ERROR[1436]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/1*7403-00000005
[Jun 19 17:29:40] ERROR[1436]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/1*7403-00000005
    -- Executing [7405@default:1] AGI("SIP/1*7403-00000005", "agi.php") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/agi.php
<SIP/1*7403-00000005>AGI Tx >> agi_request: agi.php
<SIP/1*7403-00000005>AGI Tx >> agi_channel: SIP/1*7403-00000005
<SIP/1*7403-00000005>AGI Tx >> agi_language: en
<SIP/1*7403-00000005>AGI Tx >> agi_type: SIP
<SIP/1*7403-00000005>AGI Tx >> agi_uniqueid: ehtestvm-1718803780.5
<SIP/1*7403-00000005>AGI Tx >> agi_version: 18.22.0
<SIP/1*7403-00000005>AGI Tx >> agi_callerid: 7403
<SIP/1*7403-00000005>AGI Tx >> agi_calleridname: 7403
<SIP/1*7403-00000005>AGI Tx >> agi_callingpres: 0
<SIP/1*7403-00000005>AGI Tx >> agi_callingani2: 0
<SIP/1*7403-00000005>AGI Tx >> agi_callington: 0
<SIP/1*7403-00000005>AGI Tx >> agi_callingtns: 0
<SIP/1*7403-00000005>AGI Tx >> agi_dnid: 7405
<SIP/1*7403-00000005>AGI Tx >> agi_rdnis: unknown
<SIP/1*7403-00000005>AGI Tx >> agi_context: default
<SIP/1*7403-00000005>AGI Tx >> agi_extension: 7405
<SIP/1*7403-00000005>AGI Tx >> agi_priority: 1
<SIP/1*7403-00000005>AGI Tx >> agi_enhanced: 0.0
<SIP/1*7403-00000005>AGI Tx >> agi_accountcode: 5577864113
<SIP/1*7403-00000005>AGI Tx >> agi_threadid: 140018926560960
<SIP/1*7403-00000005>AGI Tx >>
<SIP/1*7403-00000005>AGI Rx << Starting AGI script
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << AGI object created
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << Inside TpadPBX constructor
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << Inside get agi request
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << before caller id
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << after caller id
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << thi is after caller id set unknown
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << this is before isolate cid
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << inside isolate cid functio
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << this is after isolate cid
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << this is before  get cdr cid
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << this is after get cdr cid
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
    -- <SIP/1*7403-00000005>AGI Script agi.php completed, returning 0
    -- Auto fallthrough, channel 'SIP/1*7403-00000005' status is 'UNKNOWN'
    -- Executing [h@default:1] AGI("SIP/1*7403-00000005", "agi.php,CDR") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/agi.php
<SIP/1*7403-00000005>AGI Tx >> agi_request: agi.php
<SIP/1*7403-00000005>AGI Tx >> agi_channel: SIP/1*7403-00000005
<SIP/1*7403-00000005>AGI Tx >> agi_language: en
<SIP/1*7403-00000005>AGI Tx >> agi_type: SIP
<SIP/1*7403-00000005>AGI Tx >> agi_uniqueid: ehtestvm-1718803780.5
<SIP/1*7403-00000005>AGI Tx >> agi_version: 18.22.0
<SIP/1*7403-00000005>AGI Tx >> agi_callerid: 7403
<SIP/1*7403-00000005>AGI Tx >> agi_calleridname: 7403
<SIP/1*7403-00000005>AGI Tx >> agi_callingpres: 0
<SIP/1*7403-00000005>AGI Tx >> agi_callingani2: 0
<SIP/1*7403-00000005>AGI Tx >> agi_callington: 0
<SIP/1*7403-00000005>AGI Tx >> agi_callingtns: 0
<SIP/1*7403-00000005>AGI Tx >> agi_dnid: 7405
<SIP/1*7403-00000005>AGI Tx >> agi_rdnis: unknown
<SIP/1*7403-00000005>AGI Tx >> agi_context: default
<SIP/1*7403-00000005>AGI Tx >> agi_extension: h
<SIP/1*7403-00000005>AGI Tx >> agi_priority: 1
<SIP/1*7403-00000005>AGI Tx >> agi_enhanced: 0.0
<SIP/1*7403-00000005>AGI Tx >> agi_accountcode: 5577864113
<SIP/1*7403-00000005>AGI Tx >> agi_threadid: 140018926560960
<SIP/1*7403-00000005>AGI Tx >> agi_arg_1: CDR
<SIP/1*7403-00000005>AGI Tx >>
<SIP/1*7403-00000005>AGI Rx << Starting AGI script
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << AGI object created
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << Inside TpadPBX constructor
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << Inside get agi request
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << before caller id
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << after caller id
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << thi is after caller id set unknown
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << this is before isolate cid
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << inside isolate cid functio
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << this is after isolate cid
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << this is before  get cdr cid
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000005>AGI Rx << this is after get cdr cid
<SIP/1*7403-00000005>AGI Tx >> 510 Invalid or unknown command
    -- <SIP/1*7403-00000005>AGI Script agi.php completed, returning 0
ehtestvm*CLI>
ehtestvm*CLI>
ehtestvm*CLI>
ehtestvm*CLI>
ehtestvm*CLI>
ehtestvm*CLI>
ehtestvm*CLI>
ehtestvm*CLI>
ehtestvm*CLI>
[Jun 19 17:30:36] WARNING[1462][C-00000007]: sip/config_parser.c:818 sip_parse_nat_option: nat=yes is deprecated, use nat=force_rport,comedia instead
[Jun 19 17:30:36] WARNING[1462][C-00000007]: sip/config_parser.c:818 sip_parse_nat_option: nat=yes is deprecated, use nat=force_rport,comedia instead
[Jun 19 17:30:36] WARNING[1462][C-00000007]: sip/config_parser.c:818 sip_parse_nat_option: nat=yes is deprecated, use nat=force_rport,comedia instead
[Jun 19 17:30:36] WARNING[1462][C-00000007]: sip/config_parser.c:818 sip_parse_nat_option: nat=yes is deprecated, use nat=force_rport,comedia instead
[Jun 19 17:30:36] WARNING[1462][C-00000007]: sip/config_parser.c:818 sip_parse_nat_option: nat=yes is deprecated, use nat=force_rport,comedia instead
[Jun 19 17:30:36] WARNING[1462][C-00000007]: sip/config_parser.c:818 sip_parse_nat_option: nat=yes is deprecated, use nat=force_rport,comedia instead
  == Using SIP VIDEO CoS mark 6
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
[Jun 19 17:30:36] ERROR[1436]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/1*7403-00000006
[Jun 19 17:30:36] ERROR[1436]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/1*7403-00000006
[Jun 19 17:30:36] ERROR[1436]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/1*7403-00000006
    -- Executing [7405@default:1] AGI("SIP/1*7403-00000006", "agi.php") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/agi.php
<SIP/1*7403-00000006>AGI Tx >> agi_request: agi.php
<SIP/1*7403-00000006>AGI Tx >> agi_channel: SIP/1*7403-00000006
<SIP/1*7403-00000006>AGI Tx >> agi_language: en
<SIP/1*7403-00000006>AGI Tx >> agi_type: SIP
<SIP/1*7403-00000006>AGI Tx >> agi_uniqueid: ehtestvm-1718803836.6
<SIP/1*7403-00000006>AGI Tx >> agi_version: 18.22.0
<SIP/1*7403-00000006>AGI Tx >> agi_callerid: 7403
<SIP/1*7403-00000006>AGI Tx >> agi_calleridname: 7403
<SIP/1*7403-00000006>AGI Tx >> agi_callingpres: 0
<SIP/1*7403-00000006>AGI Tx >> agi_callingani2: 0
<SIP/1*7403-00000006>AGI Tx >> agi_callington: 0
<SIP/1*7403-00000006>AGI Tx >> agi_callingtns: 0
<SIP/1*7403-00000006>AGI Tx >> agi_dnid: 7405
<SIP/1*7403-00000006>AGI Tx >> agi_rdnis: unknown
<SIP/1*7403-00000006>AGI Tx >> agi_context: default
<SIP/1*7403-00000006>AGI Tx >> agi_extension: 7405
<SIP/1*7403-00000006>AGI Tx >> agi_priority: 1
<SIP/1*7403-00000006>AGI Tx >> agi_enhanced: 0.0
<SIP/1*7403-00000006>AGI Tx >> agi_accountcode: 5577864113
<SIP/1*7403-00000006>AGI Tx >> agi_threadid: 140018925024960
<SIP/1*7403-00000006>AGI Tx >>
<SIP/1*7403-00000006>AGI Rx << Starting AGI script
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << AGI object created
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << Inside TpadPBX constructor
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << Inside get agi request
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << before caller id
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << after caller id
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << thi is after caller id set unknown
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << this is before isolate cid
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << inside isolate cid functio
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << this is after isolate cid
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << this is before  get cdr cid
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
    -- <SIP/1*7403-00000006>AGI Script agi.php completed, returning 0
    -- Auto fallthrough, channel 'SIP/1*7403-00000006' status is 'UNKNOWN'
    -- Executing [h@default:1] AGI("SIP/1*7403-00000006", "agi.php,CDR") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/agi.php
<SIP/1*7403-00000006>AGI Tx >> agi_request: agi.php
<SIP/1*7403-00000006>AGI Tx >> agi_channel: SIP/1*7403-00000006
<SIP/1*7403-00000006>AGI Tx >> agi_language: en
<SIP/1*7403-00000006>AGI Tx >> agi_type: SIP
<SIP/1*7403-00000006>AGI Tx >> agi_uniqueid: ehtestvm-1718803836.6
<SIP/1*7403-00000006>AGI Tx >> agi_version: 18.22.0
<SIP/1*7403-00000006>AGI Tx >> agi_callerid: 7403
<SIP/1*7403-00000006>AGI Tx >> agi_calleridname: 7403
<SIP/1*7403-00000006>AGI Tx >> agi_callingpres: 0
<SIP/1*7403-00000006>AGI Tx >> agi_callingani2: 0
<SIP/1*7403-00000006>AGI Tx >> agi_callington: 0
<SIP/1*7403-00000006>AGI Tx >> agi_callingtns: 0
<SIP/1*7403-00000006>AGI Tx >> agi_dnid: 7405
<SIP/1*7403-00000006>AGI Tx >> agi_rdnis: unknown
<SIP/1*7403-00000006>AGI Tx >> agi_context: default
<SIP/1*7403-00000006>AGI Tx >> agi_extension: h
<SIP/1*7403-00000006>AGI Tx >> agi_priority: 1
<SIP/1*7403-00000006>AGI Tx >> agi_enhanced: 0.0
<SIP/1*7403-00000006>AGI Tx >> agi_accountcode: 5577864113
<SIP/1*7403-00000006>AGI Tx >> agi_threadid: 140018925024960
<SIP/1*7403-00000006>AGI Tx >> agi_arg_1: CDR
<SIP/1*7403-00000006>AGI Tx >>
<SIP/1*7403-00000006>AGI Rx << Starting AGI script
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << AGI object created
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << Inside TpadPBX constructor
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << Inside get agi request
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << before caller id
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << after caller id
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << thi is after caller id set unknown
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << this is before isolate cid
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << inside isolate cid functio
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << this is after isolate cid
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-00000006>AGI Rx << this is before  get cdr cid
<SIP/1*7403-00000006>AGI Tx >> 510 Invalid or unknown command
    -- <SIP/1*7403-00000006>AGI Script agi.php completed, returning 0

The peers are connected succesfully as said in my previopus reply.

The cdr.conf is:

[csv]
usegmtime=yes    ; log date/time in GMT.  Default is "no"
loguniqueid=yes  ; log uniqueid.  Default is "no"
loguserfield=yes ; log user field.  Default is "no"
accountlogs=yes  ; create separate log file for each account code. Default is "yes"
;newcdrcolumns=yes ; Enable logging of post-1.8 CDR columns (peeraccount, linkedid, sequence).
                   ; Default is "no".

[radius]
;usegmtime=yes    ; log date/time in GMT
;loguniqueid=yes  ; log uniqueid
;loguserfield=yes ; log user field
; Set this to the location of the radiusclient-ng configuration file
; The default is /etc/radiusclient-ng/radiusclient.conf
;radiuscfg => /usr/local/etc/radiusclient-ng/radiusclient.confi
radiuscfg => /etc/radcli/radiusclient.conf

My cdr_mysql.conf is:

[columns]
;static "<value>" => <column>
;alias <cdrvar> => <column>
alias start => calldate
;alias clid => <a_field_not_named_clid>
;alias src => <a_field_not_named_src>
;alias dst => <a_field_not_named_dst>
;alias dcontext => <a_field_not_named_dcontext>
;alias channel => <a_field_not_named_channel>
;alias dstchannel => <a_field_not_named_dstchannel>
;alias lastapp => <a_field_not_named_lastapp>
;alias lastdata => <a_field_not_named_lastdata>
;alias duration => <a_field_not_named_duration>
;alias billsec => <a_field_not_named_billsec>
;alias disposition => <a_field_not_named_disposition>
;alias amaflags => <a_field_not_named_amaflags>
;alias accountcode => <a_field_not_named_accountcode>
;alias userfield => <a_field_not_named_userfield>
;alias uniqueid => <a_field_not_named_uniqueid>
10

What is the output of the “cdr show status” CLI command?

11 
 cdr show status

Call Detail Record (CDR) settings
----------------------------------
  Logging:                    Enabled
  Mode:                       Simple
  Log calls by default:       Yes
  Log unanswered calls:       No
  Log congestion:             No

  Ignore bridging changes:    No

  Ignore dial state changes:  No

* Registered Backends
  -------------------
    cdr_manager (suspended)
    csv
    radius
    cdr-custom
    Adaptive ODBC
12

I’m not sure then, CDR is not my thing.

13

could you tag/point someone one who might help me in this? if the issue is related to CDR…

14

If anyone wishes to comment or participate, then they will.

15

Can some expert shed some light to this thread and point me in the right direction?

I have even downgraded my php to php 5.5 but it continues to give below messgaes on asterisk CLI aftwer setting “agi set debug on”:

[Jun 20 20:53:23] WARNING[1462][C-0000001b]: sip/config_parser.c:818 sip_parse_nat_option: nat=yes is deprecated, use nat=force_rport,comedia instead
[Jun 20 20:53:23] WARNING[1462][C-0000001b]: sip/config_parser.c:818 sip_parse_nat_option: nat=yes is deprecated, use nat=force_rport,comedia instead
[Jun 20 20:53:23] WARNING[1462][C-0000001b]: sip/config_parser.c:818 sip_parse_nat_option: nat=yes is deprecated, use nat=force_rport,comedia instead
[Jun 20 20:53:24] WARNING[1462][C-0000001b]: sip/config_parser.c:818 sip_parse_nat_option: nat=yes is deprecated, use nat=force_rport,comedia instead
[Jun 20 20:53:24] WARNING[1462][C-0000001b]: sip/config_parser.c:818 sip_parse_nat_option: nat=yes is deprecated, use nat=force_rport,comedia instead
[Jun 20 20:53:24] WARNING[1462][C-0000001b]: sip/config_parser.c:818 sip_parse_nat_option: nat=yes is deprecated, use nat=force_rport,comedia instead
  == Using SIP VIDEO CoS mark 6
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
[Jun 20 20:53:24] ERROR[1436]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/1*7403-0000001a
[Jun 20 20:53:24] ERROR[1436]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/1*7403-0000001a
[Jun 20 20:53:24] ERROR[1436]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/1*7403-0000001a
0x7f58c8006da0 - Created CDR for channel SIP/1*7403-0000001a
0x7f58c8006da0 - Transitioning CDR for SIP/1*7403-0000001a from state NONE to Single
    -- Executing [7405@default:1] AGI("SIP/1*7403-0000001a", "agi.php") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/agi.php
<SIP/1*7403-0000001a>AGI Tx >> agi_request: agi.php
<SIP/1*7403-0000001a>AGI Tx >> agi_channel: SIP/1*7403-0000001a
<SIP/1*7403-0000001a>AGI Tx >> agi_language: en
<SIP/1*7403-0000001a>AGI Tx >> agi_type: SIP
<SIP/1*7403-0000001a>AGI Tx >> agi_uniqueid: ehtestvm-1718902404.26
<SIP/1*7403-0000001a>AGI Tx >> agi_version: 18.22.0
<SIP/1*7403-0000001a>AGI Tx >> agi_callerid: 7403
<SIP/1*7403-0000001a>AGI Tx >> agi_calleridname: 7403
<SIP/1*7403-0000001a>AGI Tx >> agi_callingpres: 0
<SIP/1*7403-0000001a>AGI Tx >> agi_callingani2: 0
<SIP/1*7403-0000001a>AGI Tx >> agi_callington: 0
<SIP/1*7403-0000001a>AGI Tx >> agi_callingtns: 0
<SIP/1*7403-0000001a>AGI Tx >> agi_dnid: 7405
<SIP/1*7403-0000001a>AGI Tx >> agi_rdnis: unknown
<SIP/1*7403-0000001a>AGI Tx >> agi_context: default
<SIP/1*7403-0000001a>AGI Tx >> agi_extension: 7405
<SIP/1*7403-0000001a>AGI Tx >> agi_priority: 1
<SIP/1*7403-0000001a>AGI Tx >> agi_enhanced: 0.0
<SIP/1*7403-0000001a>AGI Tx >> agi_accountcode: 5577864113
<SIP/1*7403-0000001a>AGI Tx >> agi_threadid: 140018922976960
<SIP/1*7403-0000001a>AGI Tx >>
<SIP/1*7403-0000001a>AGI Rx <<
<SIP/1*7403-0000001a>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-0000001a>AGI Rx << Starting AGI script
<SIP/1*7403-0000001a>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-0000001a>AGI Rx << inisde Tpadpbx class
<SIP/1*7403-0000001a>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-0000001a>AGI Rx << inside main construct func
<SIP/1*7403-0000001a>AGI Tx >> 510 Invalid or unknown command
    -- <SIP/1*7403-0000001a>AGI Script agi.php completed, returning 0
    -- Auto fallthrough, channel 'SIP/1*7403-0000001a' status is 'UNKNOWN'
    -- Executing [h@default:1] AGI("SIP/1*7403-0000001a", "agi.php,CDR") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/agi.php
<SIP/1*7403-0000001a>AGI Tx >> agi_request: agi.php
<SIP/1*7403-0000001a>AGI Tx >> agi_channel: SIP/1*7403-0000001a
<SIP/1*7403-0000001a>AGI Tx >> agi_language: en
<SIP/1*7403-0000001a>AGI Tx >> agi_type: SIP
<SIP/1*7403-0000001a>AGI Tx >> agi_uniqueid: ehtestvm-1718902404.26
<SIP/1*7403-0000001a>AGI Tx >> agi_version: 18.22.0
<SIP/1*7403-0000001a>AGI Tx >> agi_callerid: 7403
<SIP/1*7403-0000001a>AGI Tx >> agi_calleridname: 7403
<SIP/1*7403-0000001a>AGI Tx >> agi_callingpres: 0
<SIP/1*7403-0000001a>AGI Tx >> agi_callingani2: 0
<SIP/1*7403-0000001a>AGI Tx >> agi_callington: 0
<SIP/1*7403-0000001a>AGI Tx >> agi_callingtns: 0
<SIP/1*7403-0000001a>AGI Tx >> agi_dnid: 7405
<SIP/1*7403-0000001a>AGI Tx >> agi_rdnis: unknown
<SIP/1*7403-0000001a>AGI Tx >> agi_context: default
<SIP/1*7403-0000001a>AGI Tx >> agi_extension: h
<SIP/1*7403-0000001a>AGI Tx >> agi_priority: 1
<SIP/1*7403-0000001a>AGI Tx >> agi_enhanced: 0.0
<SIP/1*7403-0000001a>AGI Tx >> agi_accountcode: 5577864113
<SIP/1*7403-0000001a>AGI Tx >> agi_threadid: 140018922976960
<SIP/1*7403-0000001a>AGI Tx >> agi_arg_1: CDR
<SIP/1*7403-0000001a>AGI Tx >>
<SIP/1*7403-0000001a>AGI Rx <<
<SIP/1*7403-0000001a>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-0000001a>AGI Rx << Starting AGI script
<SIP/1*7403-0000001a>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-0000001a>AGI Rx << inisde Tpadpbx class
<SIP/1*7403-0000001a>AGI Tx >> 510 Invalid or unknown command
<SIP/1*7403-0000001a>AGI Rx << inside main construct func
<SIP/1*7403-0000001a>AGI Tx >> 510 Invalid or unknown command
    -- <SIP/1*7403-0000001a>AGI Script agi.php completed, returning 0
0x7f58c8006da0 - Beginning finalize/dispatch for SIP/1*7403-0000001a
0x7f58c8006da0 - Dispatching CDR for Party A SIP/1*7403-0000001a, Party B <none>

I have set the shebang of my code as:

#!/usr/local/php5.5/bin/php

The file isx executable and runs fine when i give this path and then the /var/lib/asterisk/agi-bin/agi.php path…

16

You are writing logging information on standard output, which will look like invalid requests to the AGI code. You need to open a file and write it to that.

17

Some additional debugging after trying to simply run an agitest.php file with the following details:

agitest.php:

#!/usr/local/php5.5/bin/php
<?php
require_once('/var/lib/asterisk/agi-bin/phpagi-asmanager.php');

$agi = new AGI();
$agi->answer();
$agi->say_phonetic("Hello World");
$agi->hangup();
?>

extensions.conf:

[default]
exten => _X.,1,Answer()
exten => _X.,2,AGI(agitest.php)
exten => _X.,3,Hangup()

call logs using tail -f /var/log/asterisk/full:

[Jun 20 21:15:34] DEBUG[1462][C-0000001e] netsock2.c: Splitting '10.10.7.84' into...
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] netsock2.c: ...host '10.10.7.84' and port ''.
[Jun 20 21:15:34] WARNING[1462][C-0000001e] sip/config_parser.c: nat=yes is deprecated, use nat=force_rport,comedia instead
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] netsock2.c: Splitting '10.10.7.84' into...
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] netsock2.c: ...host '10.10.7.84' and port ''.
[Jun 20 21:15:34] WARNING[1462][C-0000001e] sip/config_parser.c: nat=yes is deprecated, use nat=force_rport,comedia instead
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] netsock2.c: Splitting '10.10.7.84' into...
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] netsock2.c: ...host '10.10.7.84' and port ''.
[Jun 20 21:15:34] WARNING[1462][C-0000001e] sip/config_parser.c: nat=yes is deprecated, use nat=force_rport,comedia instead
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 1*7403. Peer objects: 0
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x55b4e86a0620'
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] res_rtp_asterisk.c: (0x55b4e86a0620) RTP allocated port 16490
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: RTP instance '0x55b4e86a0620' is setup and ready to go
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x55b4e91d52a0'
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] res_rtp_asterisk.c: (0x55b4e91d52a0) RTP allocated port 10796
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: RTP instance '0x55b4e91d52a0' is setup and ready to go
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] netsock2.c: Splitting 'ehtestvm' into...
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] netsock2.c: ...host 'ehtestvm' and port ''.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] res_rtp_asterisk.c: () RTCP setup on RTP instance
[Jun 20 21:15:34] VERBOSE[1462][C-0000001e] netsock2.c: Using SIP VIDEO CoS mark 6
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] netsock2.c: Splitting 'ehtestvm' into...
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] netsock2.c: ...host 'ehtestvm' and port ''.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] res_rtp_asterisk.c: () RTCP setup on RTP instance
[Jun 20 21:15:34] VERBOSE[1462][C-0000001e] netsock2.c: Using SIP RTP TOS bits 184
[Jun 20 21:15:34] VERBOSE[1462][C-0000001e] netsock2.c: Using SIP RTP CoS mark 5
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Setting NAT on RTP to On
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Setting NAT on VRTP to On
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Processing session-level SDP o=sdp_admin 65546373 252805455 IN IP4 10.10.7.84... OK.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Processing session-level SDP s=A conversation... UNSUPPORTED OR FAILED.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] netsock2.c: Splitting '10.10.7.84' into...
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] netsock2.c: ...host '10.10.7.84' and port ''.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Processing session-level SDP c=IN IP4 10.10.7.84... OK.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7f58b2fd3310
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f58b2fd3310
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f58b2fd3310
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f58b2fd3310
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Unsetting payload 9 on 0x7f58b2fd3310
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/16000... UNSUPPORTED OR FAILED.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Crossover copying tx to rx payload mapping 0 (0x55b4e918ddd8) from 0x7f58b2fd3310 to 0x7f58b2fd3310
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Crossover copying tx to rx payload mapping 8 (0x55b4e91da058) from 0x7f58b2fd3310 to 0x7f58b2fd3310
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Crossover copying tx to rx payload mapping 18 (0x55b4e930aea8) from 0x7f58b2fd3310 to 0x7f58b2fd3310
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Crossover copying tx to rx payload mapping 101 (0x55b4e930b6e8) from 0x7f58b2fd3310 to 0x7f58b2fd3310
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] acl.c: For destination '10.10.7.84', our source address is '10.10.7.31'.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] res_rtp_asterisk.c: (0x55b4e86a0620) RTCP setting address on RTP instance
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Copying rx payload mapping 0 (0x55b4e918ddd8) from 0x7f58b2fd3310 to 0x55b4e86a07f8
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Copying rx payload mapping 8 (0x55b4e91da058) from 0x7f58b2fd3310 to 0x55b4e86a07f8
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Copying rx payload mapping 18 (0x55b4e930aea8) from 0x7f58b2fd3310 to 0x55b4e86a07f8
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Copying rx payload mapping 101 (0x55b4e930b6e8) from 0x7f58b2fd3310 to 0x55b4e86a07f8
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Copying tx payload mapping 0 (0x55b4e918ddd8) from 0x7f58b2fd3310 to 0x55b4e86a07f8
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Copying tx payload mapping 8 (0x55b4e91da058) from 0x7f58b2fd3310 to 0x55b4e86a07f8
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Copying tx payload mapping 18 (0x55b4e930aea8) from 0x7f58b2fd3310 to 0x55b4e86a07f8
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Copying tx payload mapping 101 (0x55b4e930b6e8) from 0x7f58b2fd3310 to 0x55b4e86a07f8
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] res_rtp_asterisk.c: (0x55b4e86a0620) RTCP ignoring duplicate property
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] res_rtp_asterisk.c: (0x55b4e91d52a0) DTLS srtp - stopped timeout timer'
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] res_rtp_asterisk.c: (0x55b4e91d52a0) DTLS srtp - stopped timeout timer'
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] res_rtp_asterisk.c: () RTP Stop
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: We're settling with these formats: (alaw|ulaw)
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Checking SIP call limits for device 1*7403
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Updating call counter for incoming call
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] netsock2.c: Splitting '10.10.7.31' into...
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] netsock2.c: ...host '10.10.7.31' and port ''.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] netsock2.c: Splitting '10.10.7.31:5060' into...
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] netsock2.c: ...host '10.10.7.31' and port ''.
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] channel_internal_api.c:  <initializing>: Formats: (none)
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] channel_internal_api.c:  Channel is being initialized or destroyed
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] stasis.c: Creating topic. name: channel:ehtestvm-1718903734.31, detail:
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] stasis.c: Topic 'channel:ehtestvm-1718903734.31': 0x55b4e91903e0 created
[Jun 20 21:15:34] DEBUG[1294] threadpool.c: Increasing threadpool stasis/pool's size by 1
[Jun 20 21:15:34] DEBUG[1311] devicestate.c: No provider found, checking channel drivers for SIP - 1*7403
[Jun 20 21:15:34] DEBUG[1311] chan_sip.c: Checking device state for peer 1*7403
[Jun 20 21:15:34] DEBUG[1311] devicestate.c: Changing state for SIP/1*7403 - state 1 (Not in use)
[Jun 20 21:15:34] ERROR[1436] cdr.c: Unable to find CDR for channel SIP/1*7403-0000001d
[Jun 20 21:15:34] ERROR[1436] cdr.c: Unable to find CDR for channel SIP/1*7403-0000001d
[Jun 20 21:15:34] ERROR[1436] cdr.c: Unable to find CDR for channel SIP/1*7403-0000001d
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] channel.c: Channel 0x55b4e91f3a60 'SIP/1*7403-0000001d' allocated
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] channel_internal_api.c:  SIP/1*7403-0000001d: Formats: (alaw)
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] channel_internal_api.c:  New topology set
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: *** Our native formats are (alaw)
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: *** Joint capabilities are (alaw|ulaw)
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: *** Our capabilities are (alaw|h261|h263|h263p|h264|ulaw)
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] res_rtp_asterisk.c: (0x55b4e91d52a0) DTLS stop
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] res_rtp_asterisk.c: (0x55b4e91d52a0) DTLS srtp - stopped timeout timer'
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] res_rtp_asterisk.c: (0x55b4e91d52a0) DTLS srtp - stopped timeout timer'
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] rtp_engine.c: Destroyed RTP instance '0x55b4e91d52a0'
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: This channel will not be able to handle video.
[Jun 20 21:15:34] VERBOSE[1436] cdr.c: 0x7f58c8075890 - Created CDR for channel SIP/1*7403-0000001d
[Jun 20 21:15:34] VERBOSE[1436] cdr.c: 0x7f58c8075890 - Transitioning CDR for SIP/1*7403-0000001d from state NONE to Single
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: SIP/1*7403-0000001d: New call is still down.... Trying...
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.10.7.84:5060
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c: Allocating new SIP dialog for 110b57ab70587ede727cdd68028a3b6d@10.10.7.31:5060 - OPTIONS (No RTP)
[Jun 20 21:15:34] DEBUG[1462] acl.c: For destination '10.10.7.84', our source address is '10.10.7.31'.
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.10.7.31:5060
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c: SIP call-id changed from '110b57ab70587ede727cdd68028a3b6d@10.10.7.31:5060' to '63921f2b54cb7aa33b9a62f968fe2225@10.10.7.31:5060'
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c: Initializing initreq for method OPTIONS - callid 63921f2b54cb7aa33b9a62f968fe2225@10.10.7.31:5060
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.10.7.84:5060
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c: = Looking for  Call ID: 66814a9578fab3d5100e465e613d4661@10.10.7.31:5060 (Checking To) --From tag as6c723ad0 --To-tag 848819789
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c: Stopping retransmission on '66814a9578fab3d5100e465e613d4661@10.10.7.31:5060' of Request 102: Match Found
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c: Destroying SIP dialog 66814a9578fab3d5100e465e613d4661@10.10.7.31:5060
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c:
---------- SIP HISTORY for '66814a9578fab3d5100e465e613d4661@10.10.7.31:5060'
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c:   * SIP Call
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c:   001. NeedDestroy     Setting needdestroy because got OPTIONS response
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c:
---------- END SIP HISTORY for '66814a9578fab3d5100e465e613d4661@10.10.7.31:5060'
[Jun 20 21:15:34] DEBUG[1311] devicestate.c: No provider found, checking channel drivers for SIP - 1*7403
[Jun 20 21:15:34] DEBUG[1311] chan_sip.c: Checking device state for peer 1*7403
[Jun 20 21:15:34] DEBUG[1311] devicestate.c: Changing state for SIP/1*7403 - state 1 (Not in use)
[Jun 20 21:15:34] DEBUG[1294] threadpool.c: Increasing threadpool stasis/pool's size by 1
[Jun 20 21:15:34] DEBUG[507737][C-0000001e] pbx.c: Launching 'Answer'
[Jun 20 21:15:34] VERBOSE[507737][C-0000001e] pbx.c: Executing [7405@default:1] Answer("SIP/1*7403-0000001d", "") in new stack
[Jun 20 21:15:34] DEBUG[1294] threadpool.c: Increasing threadpool stasis/pool's size by 1
[Jun 20 21:15:34] VERBOSE[1436] cdr.c: 0x7f58c8075890 - Set answered time to 1718903734.568450
[Jun 20 21:15:34] DEBUG[1311] devicestate.c: No provider found, checking channel drivers for SIP - 1*7403
[Jun 20 21:15:34] DEBUG[1311] chan_sip.c: Checking device state for peer 1*7403
[Jun 20 21:15:34] DEBUG[1311] devicestate.c: Changing state for SIP/1*7403 - state 1 (Not in use)
[Jun 20 21:15:34] DEBUG[507737][C-0000001e] chan_sip.c: SIP answering channel: SIP/1*7403-0000001d
[Jun 20 21:15:34] DEBUG[507737][C-0000001e] res_rtp_asterisk.c: (0x55b4e86a0620) RTP setting the marker bit due to a source update
[Jun 20 21:15:34] DEBUG[507737][C-0000001e] res_rtp_asterisk.c: (0x55b4e86a0620) DTLS - ast_rtp_activate rtp=0x55b4e91e9290 - setup and perform DTLS'
[Jun 20 21:15:34] DEBUG[507737][C-0000001e] res_rtp_asterisk.c: (0x55b4e91e9290) DTLS perform handshake - ssl = (nil), setup = 0
[Jun 20 21:15:34] DEBUG[507737][C-0000001e] res_rtp_asterisk.c: (0x55b4e91e9290) DTLS perform handshake - ssl = (nil), setup = 0
[Jun 20 21:15:34] DEBUG[507737][C-0000001e] chan_sip.c: ** Our capability: (alaw|ulaw) Video flag: True Text flag: True
[Jun 20 21:15:34] DEBUG[507737][C-0000001e] chan_sip.c: ** Our prefcodec: (nothing)
[Jun 20 21:15:34] DEBUG[507737][C-0000001e] chan_sip.c: -- Done with adding codecs to SDP
[Jun 20 21:15:34] DEBUG[507737][C-0000001e] chan_sip.c: Setting framing on incoming call: 0
[Jun 20 21:15:34] DEBUG[507737][C-0000001e] chan_sip.c: Done building SDP. Settling with this capability: (alaw|ulaw)
[Jun 20 21:15:34] DEBUG[507737][C-0000001e] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.10.7.84:5060
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c: = Looking for  Call ID: 63921f2b54cb7aa33b9a62f968fe2225@10.10.7.31:5060 (Checking To) --From tag as1bd396c3 --To-tag 148576609
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c: Stopping retransmission on '63921f2b54cb7aa33b9a62f968fe2225@10.10.7.31:5060' of Request 102: Match Found
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c: Destroying SIP dialog 63921f2b54cb7aa33b9a62f968fe2225@10.10.7.31:5060
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c:
---------- SIP HISTORY for '63921f2b54cb7aa33b9a62f968fe2225@10.10.7.31:5060'
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c:   * SIP Call
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c:   001. NeedDestroy     Setting needdestroy because got OPTIONS response
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c:
---------- END SIP HISTORY for '63921f2b54cb7aa33b9a62f968fe2225@10.10.7.31:5060'
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c: = Looking for  Call ID: 1565120909987-58651465025737@10.10.7.84 (Checking From) --From tag 2528113059 --To-tag as12f77c76
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jun 20 21:15:34] DEBUG[1462][C-0000001e] chan_sip.c: Stopping retransmission on '1565120909987-58651465025737@10.10.7.84' of Response 2: Match Found
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.10.10.191:5060
[Jun 20 21:15:34] DEBUG[1462] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 213.40.29.7:5060
[Jun 20 21:15:35] DEBUG[507737][C-0000001e] res_rtp_asterisk.c: ehtestvm-1718903734.31: Seed ts: 920793019 current time: 1718903735.052473
[Jun 20 21:15:35] DEBUG[507737][C-0000001e] pbx.c: Launching 'AGI'
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] pbx.c: Executing [7405@default:2] AGI("SIP/1*7403-0000001d", "agitest.php") in new stack
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/agitest.php
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_request: agitest.php
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_channel: SIP/1*7403-0000001d
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_language: en
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_type: SIP
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_uniqueid: ehtestvm-1718903734.31
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_version: 18.22.0
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_callerid: 7403
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_calleridname: 7403
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_callingpres: 0
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_callingani2: 0
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_callington: 0
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_callingtns: 0
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_dnid: 7405
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_rdnis: unknown
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_context: default
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_extension: 7405
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_priority: 2
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_enhanced: 0.0
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_accountcode: 5577864113
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> agi_threadid: 140018926560960
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >>
[Jun 20 21:15:35] DEBUG[507737][C-0000001e] res_rtp_asterisk.c: ehtestvm-1718903734.31: Packet 2 < 15.  Ignoring
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Rx <<
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Tx >> 510 Invalid or unknown command
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] res_agi.c: <SIP/1*7403-0000001d>AGI Script agitest.php completed, returning 0
[Jun 20 21:15:35] DEBUG[507737][C-0000001e] pbx.c: Launching 'Hangup'
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] pbx.c: Executing [7405@default:3] Hangup("SIP/1*7403-0000001d", "") in new stack
[Jun 20 21:15:35] DEBUG[507737][C-0000001e] channel.c: Soft-Hanging (0x20) up channel 'SIP/1*7403-0000001d'
[Jun 20 21:15:35] DEBUG[507737][C-0000001e] pbx.c: Spawn extension (default,7405,3) exited non-zero on 'SIP/1*7403-0000001d'
[Jun 20 21:15:35] VERBOSE[507737][C-0000001e] pbx.c: Spawn extension (default, 7405, 3) exited non-zero on 'SIP/1*7403-0000001d'
[Jun 20 21:15:35] DEBUG[507737][C-0000001e] channel.c: Soft-Hanging (0x10) up channel 'SIP/1*7403-0000001d'
[Jun 20 21:15:35] DEBUG[507737][C-0000001e] channel.c: Soft-Hanging (0x80) up channel 'SIP/1*7403-0000001d'
[Jun 20 21:15:35] DEBUG[507737][C-0000001e] chan_sip.c: Updating call counter for incoming call
[Jun 20 21:15:35] DEBUG[507737][C-0000001e] res_rtp_asterisk.c: (0x55b4e86a0620) DTLS srtp - stopped timeout timer'
[Jun 20 21:15:35] DEBUG[507737][C-0000001e] res_rtp_asterisk.c: (0x55b4e86a0620) DTLS srtp - stopped timeout timer'
[Jun 20 21:15:35] DEBUG[507737][C-0000001e] res_rtp_asterisk.c: (ehtestvm-1718903734.31) RTP Stop
[Jun 20 21:15:35] DEBUG[1311] devicestate.c: No provider found, checking channel drivers for SIP - 1*7403
[Jun 20 21:15:35] DEBUG[1311] chan_sip.c: Checking device state for peer 1*7403
[Jun 20 21:15:35] DEBUG[1311] devicestate.c: Changing state for SIP/1*7403 - state 1 (Not in use)
[Jun 20 21:15:35] DEBUG[507737][C-0000001e] chan_sip.c: Trying to put 'BYE sip:1*7' onto UDP socket destined for 10.10.7.84:5060
[Jun 20 21:15:35] DEBUG[507737][C-0000001e] channel.c: Channel 0x55b4e91f3a60 'SIP/1*7403-0000001d' destroying
[Jun 20 21:15:35] VERBOSE[1436] cdr.c: 0x7f58c8075890 - Beginning finalize/dispatch for SIP/1*7403-0000001d
[Jun 20 21:15:35] VERBOSE[1436] cdr.c: 0x7f58c8075890 - Dispatching CDR for Party A SIP/1*7403-0000001d, Party B <none>
[Jun 20 21:15:35] DEBUG[507737][C-0000001e] stasis.c: Destroying topic. name: channel:ehtestvm-1718903734.31, detail:
[Jun 20 21:15:35] DEBUG[507737][C-0000001e] stasis.c: Topic 'channel:ehtestvm-1718903734.31': 0x55b4e91903e0 destroyed
[Jun 20 21:15:35] DEBUG[507737][C-0000001e] channel_internal_api.c:  <initializing>: Formats: (nothing)
[Jun 20 21:15:35] DEBUG[507737][C-0000001e] channel_internal_api.c:  Channel is being initialized or destroyed
[Jun 20 21:15:35] DEBUG[1311] devicestate.c: No provider found, checking channel drivers for SIP - 1*7403
[Jun 20 21:15:35] DEBUG[1311] chan_sip.c: Checking device state for peer 1*7403
[Jun 20 21:15:35] DEBUG[1311] devicestate.c: Changing state for SIP/1*7403 - state 1 (Not in use)
[Jun 20 21:15:35] DEBUG[1436] cdr_radius.c: Unable to create RADIUS record. CDR not recorded!
[Jun 20 21:15:35] DEBUG[1436] stasis.c: Creating topic. name: channel:ehtestvm-1718903735.32, detail:
[Jun 20 21:15:35] DEBUG[1436] stasis.c: Topic 'channel:ehtestvm-1718903735.32': 0x7f58c80272d0 created
[Jun 20 21:15:35] DEBUG[1436] stasis.c: Destroying topic. name: channel:ehtestvm-1718903735.32, detail:
[Jun 20 21:15:35] DEBUG[1436] stasis.c: Topic 'channel:ehtestvm-1718903735.32': 0x7f58c80272d0 destroyed
[Jun 20 21:15:35] DEBUG[1462] chan_sip.c: = Looking for  Call ID: 1565120909987-58651465025737@10.10.7.84 (Checking To) --From tag as12f77c76 --To-tag 2528113059
[Jun 20 21:15:35] DEBUG[1462][C-0000001e] chan_sip.c: Stopping retransmission on '1565120909987-58651465025737@10.10.7.84' of Request 102: Match Found
[Jun 20 21:15:35] DEBUG[1462] chan_sip.c: Destroying SIP dialog 1565120909987-58651465025737@10.10.7.84
[Jun 20 21:15:35] DEBUG[1462] chan_sip.c:

Not an asterisk expert so any degree of help will be highly appreciated :slight_smile:

Best,
Hisham

18

Hi @david551

Yes, these are just echo commands that i have been using to traverse into different classes within the agi.php file, I am not bothered with the invalid command. What bothers me is the fact that I am unable to dial one extension to the other when they are both reachable and on the same vlan…could you be kind enough to check my ‘full’ logs in my previous reply and guide me what am i missing?

19

If you want to output to the console without causing errors, there’s an app for that – verbose().

Your library should have an implementation.

20

HI @sedwards
Yes, you are right. But i am not really bothered with the ‘510 invalid commands’…i can just comment the echos and they will go, but i did that so I know how exactly does the call traverse the files and its subsequent classes and methods etc.

I posted the full logs while attempting to call, could you please check it out and let me know if i am missing out on something critical?

Sorry, i am not an expert in this…