[SR-Users] add_authinfo_hdr not Added in 200 OK
Seshu Kumar
gskumar12345 at gmail.com
Wed Oct 10 07:31:36 CEST 2018
Hello Henning
I have seen logs I didn't find any error per se.
I am attaching the log file.
Thank you for answering.
regards
Seshu
On Tue, Oct 9, 2018 at 11:08 PM Henning Westerholt <hw at kamailio.org> wrote:
> Am Montag, 8. Oktober 2018, 07:52:59 CEST schrieb Seshu Kumar:
> > I am using Kamailio version 5.0.4 in IMS mode.
> > I have added ims_auth in kamailio.cfg in S-Server. And added line
> > modparam("ims_auth", "add_authinfo_hdr", 1)
> >
> > I am not finding “Authentication-Info” header being added in 200 OK
> > responses. Anything more i need to enable. Kindly someone give a clue.
> >
> > Or this is known problem?
>
> Hello Seshu,
>
> do you see any errors in your kamailio log? If yes, please provide them
> here
> to look at it.
>
> Best regards,
>
> Henning
>
> --
> Henning Westerholt - https://skalatan.de/blog/
> Kamailio security assessment - https://skalatan.de/de/assessment
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20181010/eeb0a7a9/attachment.html>
-------------- next part --------------
33(27184) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1015: kex
33(27184) DEBUG: kex [kex_mod.c:156]: child_init(): rank is (1015)
33(27184) DEBUG: <core> [sruid.c:106]: sruid_init(): root for sruid is [srid-5bbd832e-6a30-] (0 / 19)
36(27187) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: tm
33(27184) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1015: tmx
35(27186) DEBUG: tm [callid.c:137]: child_init_callid(): callid: '1f9a300b2328c12e-27186 at 192.168.12.14'
33(27184) DEBUG: tmx [tmx_mod.c:260]: child_init(): rank is (1015)
33(27184) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1015: presence
36(27187) DEBUG: tm [callid.c:137]: child_init_callid(): callid: '1f9a300b2328c12e-27187 at 192.168.12.14'
36(27187) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: sl
36(27187) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: ims_dialog
36(27187) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: kex
36(27187) DEBUG: kex [kex_mod.c:156]: child_init(): rank is (1000)
36(27187) DEBUG: <core> [sruid.c:106]: sruid_init(): root for sruid is [srid-5bbd832e-6a33-] (0 / 19)
36(27187) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: tmx
36(27187) DEBUG: tmx [tmx_mod.c:260]: child_init(): rank is (1000)
36(27187) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: presence
33(27184) DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f57b1cb3b60 not found in pool
35(27186) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1002: sl
36(27187) DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f57b1cb3b60 not found in pool
33(27184) DEBUG: db_mysql [km_my_con.c:98]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@192.168.12.14/scscf
35(27186) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1002: ims_dialog
36(27187) DEBUG: db_mysql [km_my_con.c:98]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@192.168.12.14/scscf
35(27186) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1002: kex
35(27186) DEBUG: kex [kex_mod.c:156]: child_init(): rank is (1002)
35(27186) DEBUG: <core> [sruid.c:106]: sruid_init(): root for sruid is [srid-5bbd832e-6a32-] (0 / 19)
35(27186) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1002: tmx
35(27186) DEBUG: tmx [tmx_mod.c:260]: child_init(): rank is (1002)
35(27186) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1002: presence
37(27188) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: tm
37(27188) DEBUG: tm [callid.c:137]: child_init_callid(): callid: '1f9a300b2328c12e-27188 at 192.168.12.14'
37(27188) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: sl
37(27188) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: ims_dialog
37(27188) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: kex
37(27188) DEBUG: kex [kex_mod.c:156]: child_init(): rank is (1000)
37(27188) DEBUG: <core> [sruid.c:106]: sruid_init(): root for sruid is [srid-5bbd832e-6a34-] (0 / 19)
35(27186) DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f57b1cb3b60 not found in pool
37(27188) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: tmx
37(27188) DEBUG: tmx [tmx_mod.c:260]: child_init(): rank is (1000)
37(27188) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: presence
35(27186) DEBUG: db_mysql [km_my_con.c:98]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@192.168.12.14/scscf
37(27188) DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f57b1cb3b60 not found in pool
37(27188) DEBUG: db_mysql [km_my_con.c:98]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@192.168.12.14/scscf
0(27131) INFO: cdp [cdp_mod.c:244]: cdp_child_init(): ... CDiameterPeer child started
38(27189) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1001: tm
0(27131) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 0: cdp_avp
0(27131) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [0]
0(27131) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 0: ims_usrloc_scscf
38(27189) DEBUG: tm [callid.c:137]: child_init_callid(): callid: '1f9a300b2328c12e-27189 at 192.168.12.14'
38(27189) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1001: sl
38(27189) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1001: ims_dialog
38(27189) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1001: kex
38(27189) DEBUG: kex [kex_mod.c:156]: child_init(): rank is (1001)
0(27131) DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f57b1cb3b60 not found in pool
38(27189) DEBUG: <core> [sruid.c:106]: sruid_init(): root for sruid is [srid-5bbd832e-6a35-] (0 / 19)
0(27131) DEBUG: db_mysql [km_my_con.c:98]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@192.168.12.14/scscf
38(27189) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1001: tmx
38(27189) DEBUG: tmx [tmx_mod.c:260]: child_init(): rank is (1001)
38(27189) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1001: presence
38(27189) DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f57b1cb3b60 not found in pool
38(27189) DEBUG: db_mysql [km_my_con.c:98]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@192.168.12.14/scscf
21(27168) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
21(27168) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
21(27168) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
21(27168) DEBUG: presence [presence.c:533]: child_init(): child 1003: Database connection opened successfully
21(27168) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1003: dispatcher
21(27168) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1003: uac
21(27168) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1003: ctl
21(27168) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1003: jsonrpcs
21(27168) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1003: cdp
37(27188) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
37(27188) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
37(27188) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
21(27168) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1003: cdp_avp
21(27168) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [1003]
37(27188) DEBUG: presence [presence.c:533]: child_init(): child 1000: Database connection opened successfully
21(27168) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1003: ims_usrloc_scscf
37(27188) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: dispatcher
37(27188) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: uac
21(27168) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1cb3c38 found in pool
37(27188) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: ctl
21(27168) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1003: ims_registrar_scscf
21(27168) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [1003]
37(27188) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: jsonrpcs
37(27188) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: cdp
37(27188) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: cdp_avp
0(27131) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
0(27131) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
0(27131) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
37(27188) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [1000]
0(27131) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 0: ims_registrar_scscf
37(27188) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: ims_usrloc_scscf
0(27131) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [0]
37(27188) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1cb3c38 found in pool
37(27188) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: ims_registrar_scscf
37(27188) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [1000]
38(27189) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
38(27189) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
38(27189) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
38(27189) DEBUG: presence [presence.c:533]: child_init(): child 1001: Database connection opened successfully
38(27189) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1001: dispatcher
38(27189) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1001: uac
38(27189) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1001: ctl
38(27189) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1001: jsonrpcs
38(27189) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1001: cdp
39(27208) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: tm
38(27189) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1001: cdp_avp
38(27189) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [1001]
38(27189) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1001: ims_usrloc_scscf
38(27189) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1cb3c38 found in pool
35(27186) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
38(27189) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1001: ims_registrar_scscf
35(27186) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
35(27186) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
38(27189) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [1001]
35(27186) DEBUG: presence [presence.c:533]: child_init(): child 1002: Database connection opened successfully
35(27186) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1002: dispatcher
35(27186) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1002: uac
35(27186) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1002: ctl
35(27186) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1002: jsonrpcs
35(27186) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1002: cdp
35(27186) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1002: cdp_avp
35(27186) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [1002]
35(27186) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1002: ims_usrloc_scscf
35(27186) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1cb3c38 found in pool
35(27186) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1002: ims_registrar_scscf
35(27186) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [1002]
35(27186) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1002: debugger
35(27186) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1002)
35(27186) INFO: cdp [receiver.c:450]: receiver_process(): receiver_process(): [] Receiver process doing init on new process...
35(27186) INFO: cdp [receiver.c:455]: receiver_process(): receiver_process(): [] Receiver process starting up...
20(27166) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1002: debugger
19(27165) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1001: debugger
20(27166) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1002)
18(27164) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
19(27165) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1001)
18(27164) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
18(27164) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
20(27166) INFO: cdp [worker.c:332]: worker_process(): [1] Worker process started...
19(27165) INFO: cdp [worker.c:332]: worker_process(): [0] Worker process started...
18(27164) DEBUG: presence [presence.c:533]: child_init(): child -2: Database connection opened successfully
18(27164) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank -2: dispatcher
18(27164) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank -2: uac
22(27169) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
18(27164) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank -2: ctl
22(27169) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
30(27179) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
22(27169) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
30(27179) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
30(27179) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
22(27169) DEBUG: presence [presence.c:533]: child_init(): child 1004: Database connection opened successfully
30(27179) DEBUG: presence [presence.c:533]: child_init(): child 1012: Database connection opened successfully
22(27169) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1004: dispatcher
30(27179) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1012: dispatcher
18(27164) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank -2: jsonrpcs
22(27169) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1004: uac
30(27179) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1012: uac
18(27164) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank -2: cdp
22(27169) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1004: ctl
30(27179) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1012: ctl
18(27164) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank -2: cdp_avp
18(27164) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [-2]
18(27164) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank -2: ims_usrloc_scscf
30(27179) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1012: jsonrpcs
22(27169) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1004: jsonrpcs
22(27169) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1004: cdp
18(27164) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank -2: ims_registrar_scscf
30(27179) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1012: cdp
22(27169) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1004: cdp_avp
30(27179) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1012: cdp_avp
18(27164) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [-2]
30(27179) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [1012]
22(27169) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [1004]
30(27179) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1012: ims_usrloc_scscf
22(27169) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1004: ims_usrloc_scscf
22(27169) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1cb3c38 found in pool
30(27179) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1cb3c38 found in pool
30(27179) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1012: ims_registrar_scscf
22(27169) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1004: ims_registrar_scscf
30(27179) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [1012]
22(27169) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [1004]
18(27164) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank -2: debugger
18(27164) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (-2)
18(27164) INFO: jsonrpcs [jsonrpcs_sock.c:443]: jsonrpc_dgram_process(): a new child 0/27164
30(27179) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1012: debugger
22(27169) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1004: debugger
30(27179) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1012)
22(27169) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1004)
22(27169) INFO: cdp [worker.c:332]: worker_process(): [3] Worker process started...
30(27179) INFO: cdp [worker.c:332]: worker_process(): [11] Worker process started...
23(27170) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
23(27170) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
23(27170) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
23(27170) DEBUG: presence [presence.c:533]: child_init(): child 1005: Database connection opened successfully
23(27170) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1005: dispatcher
23(27170) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1005: uac
23(27170) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1005: ctl
23(27170) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1005: jsonrpcs
23(27170) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1005: cdp
23(27170) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1005: cdp_avp
23(27170) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [1005]
23(27170) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1005: ims_usrloc_scscf
23(27170) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1cb3c38 found in pool
23(27170) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1005: ims_registrar_scscf
23(27170) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [1005]
24(27171) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
24(27171) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
24(27171) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
24(27171) DEBUG: presence [presence.c:533]: child_init(): child 1006: Database connection opened successfully
24(27171) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1006: dispatcher
24(27171) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1006: uac
24(27171) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1006: ctl
24(27171) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1006: jsonrpcs
24(27171) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1006: cdp
24(27171) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1006: cdp_avp
24(27171) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [1006]
24(27171) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1006: ims_usrloc_scscf
24(27171) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1cb3c38 found in pool
24(27171) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1006: ims_registrar_scscf
24(27171) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [1006]
23(27170) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1005: debugger
23(27170) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1005)
23(27170) INFO: cdp [worker.c:332]: worker_process(): [4] Worker process started...
24(27171) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1006: debugger
24(27171) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1006)
24(27171) INFO: cdp [worker.c:332]: worker_process(): [5] Worker process started...
29(27178) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
29(27178) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
29(27178) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
29(27178) DEBUG: presence [presence.c:533]: child_init(): child 1011: Database connection opened successfully
25(27172) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
29(27178) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1011: dispatcher
28(27175) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1010: debugger
25(27172) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
29(27178) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1011: uac
25(27172) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
28(27175) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1010)
25(27172) DEBUG: presence [presence.c:533]: child_init(): child 1007: Database connection opened successfully
29(27178) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1011: ctl
25(27172) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1007: dispatcher
28(27175) INFO: cdp [worker.c:332]: worker_process(): [9] Worker process started...
25(27172) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1007: uac
29(27178) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1011: jsonrpcs
25(27172) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1007: ctl
29(27178) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1011: cdp
16(27158) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank -2: debugger
29(27178) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1011: cdp_avp
16(27158) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (-2)
25(27172) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1007: jsonrpcs
29(27178) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [1011]
16(27158) DEBUG: ctl [ctl.c:329]: mod_child(): ctl: mod_child(0), fork_process=0, csl=0x1acb500
25(27172) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1007: cdp
16(27158) DEBUG: ctl [ctl.c:336]: mod_child(): ctl: 0 io_listen_loop(1, 0x1acb500)
29(27178) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1011: ims_usrloc_scscf
25(27172) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1007: cdp_avp
25(27172) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [1007]
25(27172) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1007: ims_usrloc_scscf
16(27158) INFO: ctl [io_listener.c:210]: io_listen_loop(): io_listen_loop: using epoll_lt as the io watch method (auto detected)
29(27178) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1cb3c38 found in pool
29(27178) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1011: ims_registrar_scscf
25(27172) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1cb3c38 found in pool
29(27178) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [1011]
25(27172) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1007: ims_registrar_scscf
25(27172) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [1007]
16(27158) DEBUG: ctl [io_listener.c:246]: io_listen_loop(): io_listen_loop: adding socket 4, type 2, transport 3 (/var/run/kamailio_scscf/kamailio_ctl)
16(27158) DEBUG: ctl [../../core/io_wait.h:380]: io_watch_add(): DBG: io_watch_add(0x7f57ad2697c0, 4, 2, 0x1acb500), fd_no=0
27(27174) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
27(27174) DEBUG: presence [presence.c:533]: child_init(): child 1009: Database connection opened successfully
27(27174) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1009: dispatcher
27(27174) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1009: uac
27(27174) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1009: ctl
27(27174) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1009: jsonrpcs
27(27174) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1009: cdp
27(27174) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1009: cdp_avp
27(27174) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [1009]
27(27174) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1009: ims_usrloc_scscf
27(27174) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1cb3c38 found in pool
27(27174) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1009: ims_registrar_scscf
27(27174) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [1009]
29(27178) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1011: debugger
29(27178) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1011)
25(27172) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1007: debugger
25(27172) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1007)
29(27178) INFO: cdp [worker.c:332]: worker_process(): [10] Worker process started...
25(27172) INFO: cdp [worker.c:332]: worker_process(): [6] Worker process started...
27(27174) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1009: debugger
27(27174) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1009)
27(27174) INFO: cdp [worker.c:332]: worker_process(): [8] Worker process started...
34(27185) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1016: sl
34(27185) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1016: ims_dialog
34(27185) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1016: kex
34(27185) DEBUG: kex [kex_mod.c:156]: child_init(): rank is (1016)
34(27185) DEBUG: <core> [sruid.c:106]: sruid_init(): root for sruid is [srid-5bbd832e-6a31-] (0 / 19)
34(27185) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1016: tmx
34(27185) DEBUG: tmx [tmx_mod.c:260]: child_init(): rank is (1016)
31(27182) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
32(27183) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
34(27185) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1016: presence
31(27182) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
32(27183) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
31(27182) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
32(27183) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
32(27183) DEBUG: presence [presence.c:533]: child_init(): child 1014: Database connection opened successfully
31(27182) DEBUG: presence [presence.c:533]: child_init(): child 1013: Database connection opened successfully
31(27182) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1013: dispatcher
32(27183) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1014: dispatcher
31(27182) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1013: uac
32(27183) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1014: uac
31(27182) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1013: ctl
32(27183) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1014: ctl
34(27185) DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f57b1cb3b60 not found in pool
32(27183) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1014: jsonrpcs
31(27182) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1013: jsonrpcs
31(27182) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1013: cdp
32(27183) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1014: cdp
34(27185) DEBUG: db_mysql [km_my_con.c:98]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@192.168.12.14/scscf
32(27183) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1014: cdp_avp
31(27182) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1013: cdp_avp
32(27183) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [1014]
31(27182) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [1013]
31(27182) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1013: ims_usrloc_scscf
32(27183) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1014: ims_usrloc_scscf
32(27183) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1cb3c38 found in pool
31(27182) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1cb3c38 found in pool
32(27183) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1014: ims_registrar_scscf
31(27182) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1013: ims_registrar_scscf
32(27183) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [1014]
31(27182) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [1013]
34(27185) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
34(27185) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
34(27185) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
34(27185) DEBUG: presence [presence.c:533]: child_init(): child 1016: Database connection opened successfully
34(27185) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1016: dispatcher
34(27185) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1016: uac
34(27185) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1016: ctl
34(27185) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1016: jsonrpcs
34(27185) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1016: cdp
34(27185) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1016: cdp_avp
34(27185) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [1016]
34(27185) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1016: ims_usrloc_scscf
34(27185) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1cb3c38 found in pool
34(27185) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1016: ims_registrar_scscf
34(27185) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [1016]
31(27182) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1013: debugger
32(27183) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1014: debugger
31(27182) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1013)
32(27183) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1014)
31(27182) INFO: cdp [worker.c:332]: worker_process(): [12] Worker process started...
32(27183) INFO: cdp [worker.c:332]: worker_process(): [13] Worker process started...
26(27173) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1008: debugger
26(27173) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1008)
26(27173) INFO: cdp [worker.c:332]: worker_process(): [7] Worker process started...
39(27208) DEBUG: tm [callid.c:137]: child_init_callid(): callid: '1f9a300b2328c12e-27208 at 192.168.12.14'
39(27208) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: sl
39(27208) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: ims_dialog
39(27208) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: kex
39(27208) DEBUG: kex [kex_mod.c:156]: child_init(): rank is (127)
39(27208) DEBUG: <core> [sruid.c:106]: sruid_init(): root for sruid is [srid-5bbd832e-6a48-] (0 / 19)
39(27208) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: tmx
39(27208) DEBUG: tmx [tmx_mod.c:260]: child_init(): rank is (127)
39(27208) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: presence
39(27208) DEBUG: <core> [db_id.c:326]: cmp_db_id(): identical DB URLs, but different DB connection pid [27208/27131]
39(27208) DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f57b1cb3c38 not found in pool
34(27185) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1016: debugger
34(27185) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1016)
39(27208) DEBUG: db_mysql [km_my_con.c:98]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@192.168.12.14/scscf
34(27185) INFO: cdp [worker.c:332]: worker_process(): [15] Worker process started...
41(27210) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: tm
41(27210) DEBUG: tm [callid.c:137]: child_init_callid(): callid: '1f9a300b2328c12e-27210 at 192.168.12.14'
41(27210) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: sl
0(27131) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 0: debugger
41(27210) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: ims_dialog
0(27131) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (0)
41(27210) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: kex
41(27210) DEBUG: kex [kex_mod.c:156]: child_init(): rank is (127)
0(27131) DEBUG: <core> [main.c:1746]: main_loop(): Expect maximum 175 open fds
41(27210) DEBUG: <core> [sruid.c:106]: sruid_init(): root for sruid is [srid-5bbd832e-6a4a-] (0 / 19)
41(27210) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: tmx
41(27210) DEBUG: tmx [tmx_mod.c:260]: child_init(): rank is (127)
41(27210) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: presence
41(27210) DEBUG: <core> [db_id.c:326]: cmp_db_id(): identical DB URLs, but different DB connection pid [27210/27131]
41(27210) DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f57b1cb3c38 not found in pool
41(27210) DEBUG: db_mysql [km_my_con.c:98]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@192.168.12.14/scscf
39(27208) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
40(27209) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: tm
36(27187) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
39(27208) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
39(27208) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
36(27187) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
36(27187) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
36(27187) DEBUG: presence [presence.c:533]: child_init(): child 1000: Database connection opened successfully
39(27208) DEBUG: presence [presence.c:533]: child_init(): child 127: Database connection opened successfully
36(27187) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: dispatcher
39(27208) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: dispatcher
36(27187) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: uac
39(27208) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: uac
36(27187) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: ctl
39(27208) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: ctl
36(27187) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: jsonrpcs
39(27208) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: jsonrpcs
36(27187) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: cdp
39(27208) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: cdp
36(27187) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: cdp_avp
39(27208) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: cdp_avp
36(27187) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [1000]
36(27187) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: ims_usrloc_scscf
39(27208) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [127]
36(27187) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1cb3c38 found in pool
39(27208) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: ims_usrloc_scscf
40(27209) DEBUG: tm [callid.c:137]: child_init_callid(): callid: '1f9a300b2328c12e-27209 at 192.168.12.14'
36(27187) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: ims_registrar_scscf
40(27209) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: sl
36(27187) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [1000]
40(27209) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: ims_dialog
40(27209) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: kex
40(27209) DEBUG: kex [kex_mod.c:156]: child_init(): rank is (127)
39(27208) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1c7b470 found in pool
40(27209) DEBUG: <core> [sruid.c:106]: sruid_init(): root for sruid is [srid-5bbd832e-6a49-] (0 / 19)
39(27208) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: ims_registrar_scscf
40(27209) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: tmx
39(27208) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [127]
40(27209) DEBUG: tmx [tmx_mod.c:260]: child_init(): rank is (127)
40(27209) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: presence
40(27209) DEBUG: <core> [db_id.c:326]: cmp_db_id(): identical DB URLs, but different DB connection pid [27209/27131]
40(27209) DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f57b1cb3c38 not found in pool
40(27209) DEBUG: db_mysql [km_my_con.c:98]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@192.168.12.14/scscf
37(27188) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: debugger
37(27188) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1000)
21(27168) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1003: debugger
37(27188) INFO: cdp [acceptor.c:81]: acceptor_process(): Acceptor process starting up...
21(27168) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1003)
21(27168) INFO: cdp [worker.c:332]: worker_process(): [2] Worker process started...
37(27188) DEBUG: cdp [tcp_accept.c:114]: create_socket(): create_sockets: create socket and bind for IPv4...
42(27211) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: tm
37(27188) WARNING: cdp [tcp_accept.c:121]: create_socket(): create_socket(): Trying to open/bind/listen on 192.168.12.14 port 3870
38(27189) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1001: debugger
38(27189) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1001)
37(27188) WARNING: cdp [tcp_accept.c:146]: create_socket(): create_socket(): Successful socket open/bind/listen on 192.168.12.14 port 3870
37(27188) INFO: cdp [acceptor.c:95]: acceptor_process(): Acceptor opened sockets. Entering accept loop ...
42(27211) DEBUG: tm [callid.c:137]: child_init_callid(): callid: '1f9a300b2328c12e-27211 at 192.168.12.14'
38(27189) INFO: cdp [timer.c:205]: timer_process(): Timer process starting up...
42(27211) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: sl
42(27211) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: ims_dialog
33(27184) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
42(27211) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: kex
41(27210) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
33(27184) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
33(27184) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
41(27210) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
38(27189) DEBUG: cdp [peermanager.c:280]: peer_timer(): peer_timer(): Peer hss.tera-ims.in State 0
41(27210) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
root at debian:/home/koffee# 33(27184) DEBUG: presence [presence.c:533]: child_init(): child 1015: Database connection opened successfully
38(27189) DEBUG: cdp [peerstatemachine.c:90]: sm_process(): sm_process(): Peer hss.tera-ims.in State Closed Event Start
41(27210) DEBUG: presence [presence.c:533]: child_init(): child 127: Database connection opened successfully
38(27189) INFO: cdp [peerstatemachine.c:525]: I_Snd_Conn_Req(): I_Snd_Conn_Req(): Peer hss.tera-ims.in
36(27187) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1000: debugger
33(27184) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1015: dispatcher
41(27210) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: dispatcher
36(27187) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1000)
33(27184) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1015: uac
41(27210) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: uac
33(27184) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1015: ctl
41(27210) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: ctl
36(27187) INFO: cdp [receiver.c:450]: receiver_process(): receiver_process(): [hss.tera-ims.in] Receiver process doing init on new process...
36(27187) INFO: cdp [receiver.c:184]: add_serviced_peer(): add_serviced_peer(): Adding serviced_peer_t to receiver for peer [hss.tera-ims.in]
33(27184) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1015: jsonrpcs
41(27210) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: jsonrpcs
33(27184) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1015: cdp
41(27210) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: cdp
33(27184) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1015: cdp_avp
41(27210) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: cdp_avp
33(27184) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [1015]
41(27210) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [127]
33(27184) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1015: ims_usrloc_scscf
41(27210) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: ims_usrloc_scscf
41(27210) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1c7b470 found in pool
33(27184) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1cb3c38 found in pool
36(27187) INFO: cdp [receiver.c:455]: receiver_process(): receiver_process(): [hss.tera-ims.in] Receiver process starting up...
41(27210) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: ims_registrar_scscf
33(27184) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1015: ims_registrar_scscf
41(27210) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [127]
33(27184) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [1015]
40(27209) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
40(27209) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
40(27209) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
40(27209) DEBUG: presence [presence.c:533]: child_init(): child 127: Database connection opened successfully
40(27209) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: dispatcher
40(27209) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: uac
40(27209) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: ctl
40(27209) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: jsonrpcs
40(27209) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: cdp
40(27209) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: cdp_avp
40(27209) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [127]
40(27209) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: ims_usrloc_scscf
40(27209) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1c7b470 found in pool
40(27209) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: ims_registrar_scscf
40(27209) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [127]
38(27189) INFO: cdp [receiver.c:869]: peer_connect(): peer_connect(): Trying to connect to 192.168.12.14 port 3868
38(27189) INFO: cdp [receiver.c:937]: peer_connect(): peer_connect(): Peer hss.tera-ims.in:3868 connected
36(27187) DEBUG: cdp [receiver.c:697]: receive_loop(): select_recv(): There is something on the fd exchange pipe
36(27187) DEBUG: cdp [receiver.c:706]: receive_loop(): select_recv(): fd exchange pipe says fd [14] for peer 0x7f57a79ce510:[hss.tera-ims.in]
36(27187) DEBUG: cdp [peerstatemachine.c:90]: sm_process(): sm_process(): Peer hss.tera-ims.in State Wait_Conn_Ack Event I_Rcv_Conn_Ack
36(27187) DEBUG: cdp [diameter_msg.c:184]: AAANewMessage(): AAANewMessage: param session received null and it's a request!!
41(27210) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: debugger
41(27210) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (127)
41(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:2255]: notification_event_process(): Running notification_event_process33(27184) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 1015: debugger
39(27208) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: debugger
42(27211) DEBUG: kex [kex_mod.c:156]: child_init(): rank is (127)
33(27184) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (1015)
39(27208) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (127)
36(27187) DEBUG: cdp [diameter_msg.c:81]: AAABuildMsgBuffer(): AAABuildMsgBuffer(): len=304
39(27208) DEBUG: ims_registrar_scscf [registrar_notify.c:2255]: notification_event_process(): Running notification_event_process42(27211) DEBUG: <core> [sruid.c:106]: sruid_init(): root for sruid is [srid-5bbd832e-6a4b-] (0 / 19)
33(27184) INFO: cdp [worker.c:332]: worker_process(): [14] Worker process started...
42(27211) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: tmx
42(27211) DEBUG: tmx [tmx_mod.c:260]: child_init(): rank is (127)
42(27211) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: presence
36(27187) DEBUG: cdp [receiver.c:994]: peer_send_msg(): peer_send_msg(): Pipe push [0x7f57a7a593b0]
36(27187) DEBUG: cdp [receiver.c:751]: receive_loop(): select_recv(): There is something on the send pipe
36(27187) DEBUG: cdp [receiver.c:764]: receive_loop(): select_recv(): Send pipe says [0x7f57a7a593b0] 8
36(27187) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f57a7a593b0) 257
42(27211) DEBUG: <core> [db_id.c:326]: cmp_db_id(): identical DB URLs, but different DB connection pid [27211/27131]
42(27211) DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f57b1cb3c38 not found in pool
42(27211) DEBUG: db_mysql [km_my_con.c:98]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@192.168.12.14/scscf
40(27209) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: debugger
40(27209) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (127)
40(27209) DEBUG: ims_registrar_scscf [registrar_notify.c:2255]: notification_event_process(): Running notification_event_process36(27187) DEBUG: cdp [receiver.c:574]: do_receive(): receive_loop(): [hss.tera-ims.in] Recv Version 1 Length 300
36(27187) DEBUG: cdp [receiver.c:1088]: receive_message(): receive_message(): [hss.tera-ims.in] Recv msg 257
36(27187) DEBUG: cdp [peerstatemachine.c:90]: sm_process(): sm_process(): Peer hss.tera-ims.in State Wait_I_CEA Event I_Rcv_CEA
36(27187) DEBUG: cdp [peerstatemachine.c:692]: count_Supported_Vendor_Id_AVPS(): Found 0 Supported_Vendor AVPS36(27187) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f57a7a593b0) 257
42(27211) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
42(27211) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
42(27211) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
42(27211) DEBUG: presence [presence.c:533]: child_init(): child 127: Database connection opened successfully
42(27211) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: dispatcher
42(27211) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: uac
42(27211) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: ctl
42(27211) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: jsonrpcs
42(27211) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: cdp
42(27211) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: cdp_avp
42(27211) DEBUG: cdp_avp [cdp_avp_mod.c:211]: cdp_avp_child_init(): Initializing child in module cdp_avp for rank [127]
42(27211) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: ims_usrloc_scscf
42(27211) DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f57b1c7b470 found in pool
42(27211) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: ims_registrar_scscf
42(27211) DEBUG: ims_registrar_scscf [ims_registrar_scscf_mod.c:530]: child_init(): Initialization of module in child [127]
42(27211) DEBUG: <core> [core/sr_module.c:920]: init_mod_child(): rank 127: debugger
42(27211) DEBUG: debugger [debugger_mod.c:223]: child_init(): rank is (127)
42(27211) DEBUG: ims_registrar_scscf [registrar_notify.c:2255]: notification_event_process(): Running notification_event_process38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(27147) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(27147) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 69028697
13(27147) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 69028697
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
13(27147) DEBUG: dispatcher [dispatch.c:2700]: ds_check_timer(): no destination sets
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
13(27147) DEBUG: presence [subscribe.c:2499]: timer_db_update(): db_update timer
13(27147) DEBUG: presence [subscribe.c:2222]: update_db_subs_timer(): update_db_subs_timer: start
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(27147) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(27147) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 69028707
13(27147) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 69028707
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
13(27147) DEBUG: dispatcher [dispatch.c:2700]: ds_check_timer(): no destination sets
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(27147) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(27147) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 69028717
13(27147) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 69028717
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
38(27189) DEBUG: cdp [peermanager.c:280]: peer_timer(): peer_timer(): Peer hss.tera-ims.in State 6
38(27189) DEBUG: cdp [diameter_msg.c:81]: AAABuildMsgBuffer(): AAABuildMsgBuffer(): len=68
38(27189) DEBUG: cdp [receiver.c:994]: peer_send_msg(): peer_send_msg(): Pipe push [0x7f57a7a593b0]
36(27187) DEBUG: cdp [receiver.c:751]: receive_loop(): select_recv(): There is something on the send pipe
36(27187) DEBUG: cdp [receiver.c:764]: receive_loop(): select_recv(): Send pipe says [0x7f57a7a593b0] 8
36(27187) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f57a7a593b0) 280
36(27187) DEBUG: cdp [receiver.c:574]: do_receive(): receive_loop(): [hss.tera-ims.in] Recv Version 1 Length 76
36(27187) DEBUG: cdp [receiver.c:1088]: receive_message(): receive_message(): [hss.tera-ims.in] Recv msg 280
36(27187) DEBUG: cdp [peerstatemachine.c:90]: sm_process(): sm_process(): Peer hss.tera-ims.in State I_Open Event I_Rcv_DWA
36(27187) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f57a7a5a350) 280
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
13(27147) DEBUG: presence [subscribe.c:2499]: timer_db_update(): db_update timer
13(27147) DEBUG: presence [subscribe.c:2222]: update_db_subs_timer(): update_db_subs_timer: start
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(27147) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(27147) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 69028727
13(27147) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 69028727
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
13(27147) DEBUG: dispatcher [dispatch.c:2700]: ds_check_timer(): no destination sets
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(27147) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(27147) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 69028737
13(27147) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 69028737
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
13(27147) DEBUG: presence [subscribe.c:2499]: timer_db_update(): db_update timer
13(27147) DEBUG: presence [subscribe.c:2222]: update_db_subs_timer(): update_db_subs_timer: start
13(27147) DEBUG: dispatcher [dispatch.c:2700]: ds_check_timer(): no destination sets
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(27147) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(27147) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 69028747
13(27147) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 69028747
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
38(27189) DEBUG: cdp [peermanager.c:280]: peer_timer(): peer_timer(): Peer hss.tera-ims.in State 6
38(27189) DEBUG: cdp [diameter_msg.c:81]: AAABuildMsgBuffer(): AAABuildMsgBuffer(): len=68
38(27189) DEBUG: cdp [receiver.c:994]: peer_send_msg(): peer_send_msg(): Pipe push [0x7f57a7a593b0]
36(27187) DEBUG: cdp [receiver.c:751]: receive_loop(): select_recv(): There is something on the send pipe
36(27187) DEBUG: cdp [receiver.c:764]: receive_loop(): select_recv(): Send pipe says [0x7f57a7a593b0] 8
36(27187) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f57a7a593b0) 280
36(27187) DEBUG: cdp [receiver.c:574]: do_receive(): receive_loop(): [hss.tera-ims.in] Recv Version 1 Length 76
36(27187) DEBUG: cdp [receiver.c:1088]: receive_message(): receive_message(): [hss.tera-ims.in] Recv msg 280
36(27187) DEBUG: cdp [peerstatemachine.c:90]: sm_process(): sm_process(): Peer hss.tera-ims.in State I_Open Event I_Rcv_DWA
36(27187) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f57a7a5a350) 280
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(27147) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(27147) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 69028757
13(27147) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 69028757
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
13(27147) DEBUG: dispatcher [dispatch.c:2700]: ds_check_timer(): no destination sets
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
13(27147) DEBUG: presence [subscribe.c:2499]: timer_db_update(): db_update timer
13(27147) DEBUG: presence [subscribe.c:2222]: update_db_subs_timer(): update_db_subs_timer: start
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(27147) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(27147) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 69028767
13(27147) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 69028767
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
13(27147) DEBUG: ims_usrloc_scscf [ims_usrloc_scscf_mod.c:487]: timer(): Syncing cache
13(27147) DEBUG: ims_usrloc_scscf [udomain.c:277]: mem_timer_udomain(): Changing expired_contacts list size from 0 to 1024
13(27147) DEBUG: ims_usrloc_scscf [udomain.c:291]: mem_timer_udomain(): *** mem_timer_udomain - checking contacts - START ***
13(27147) DEBUG: ims_usrloc_scscf [udomain.c:353]: mem_timer_udomain(): *** mem_timer_udomain - checking contacts - FINISHED ***
13(27147) DEBUG: ims_usrloc_scscf [udomain.c:359]: mem_timer_udomain(): *** mem_timer_udomain - checking IMPUs - START ***
13(27147) DEBUG: ims_usrloc_scscf [udomain.c:384]: mem_timer_udomain(): *** mem_timer_udomain - checking IMPUs - FINISHED ***
13(27147) DEBUG: dispatcher [dispatch.c:2700]: ds_check_timer(): no destination sets
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(27147) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(27147) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 69028777
13(27147) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 69028777
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
38(27189) DEBUG: cdp [peermanager.c:280]: peer_timer(): peer_timer(): Peer hss.tera-ims.in State 6
38(27189) DEBUG: cdp [diameter_msg.c:81]: AAABuildMsgBuffer(): AAABuildMsgBuffer(): len=68
38(27189) DEBUG: cdp [receiver.c:994]: peer_send_msg(): peer_send_msg(): Pipe push [0x7f57a7a593b0]
36(27187) DEBUG: cdp [receiver.c:751]: receive_loop(): select_recv(): There is something on the send pipe
36(27187) DEBUG: cdp [receiver.c:764]: receive_loop(): select_recv(): Send pipe says [0x7f57a7a593b0] 8
36(27187) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f57a7a593b0) 280
36(27187) DEBUG: cdp [receiver.c:574]: do_receive(): receive_loop(): [hss.tera-ims.in] Recv Version 1 Length 76
36(27187) DEBUG: cdp [receiver.c:1088]: receive_message(): receive_message(): [hss.tera-ims.in] Recv msg 280
36(27187) DEBUG: cdp [peerstatemachine.c:90]: sm_process(): sm_process(): Peer hss.tera-ims.in State I_Open Event I_Rcv_DWA
36(27187) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f57a7a5a350) 280
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
13(27147) DEBUG: presence [publish.c:75]: msg_presentity_clean(): cleaning expired presentity information
13(27147) DEBUG: <core> [db_res.c:120]: db_new_result(): allocate 56 bytes for result set at 0x7f57b1cb3c38
13(27147) DEBUG: db_mysql [km_res.c:66]: db_mysql_get_columns(): 4 columns returned from the query
13(27147) DEBUG: <core> [db_res.c:158]: db_allocate_columns(): allocate 32 bytes for result names at 0x7f57b1c7b350
13(27147) DEBUG: <core> [db_res.c:169]: db_allocate_columns(): allocate 16 bytes for result types at 0x7f57b1c7b3d8
13(27147) DEBUG: db_mysql [km_res.c:84]: db_mysql_get_columns(): allocate 16 bytes for RES_NAMES[0] at 0x7f57b1c7b450
13(27147) DEBUG: db_mysql [km_res.c:91]: db_mysql_get_columns(): RES_NAMES(0x7f57b1c7b450)[0]=[username]
13(27147) DEBUG: db_mysql [km_res.c:135]: db_mysql_get_columns(): use DB1_STRING result type
13(27147) DEBUG: db_mysql [km_res.c:84]: db_mysql_get_columns(): allocate 16 bytes for RES_NAMES[1] at 0x7f57b1c7b4c8
13(27147) DEBUG: db_mysql [km_res.c:91]: db_mysql_get_columns(): RES_NAMES(0x7f57b1c7b4c8)[1]=[domain]
13(27147) DEBUG: db_mysql [km_res.c:135]: db_mysql_get_columns(): use DB1_STRING result type
13(27147) DEBUG: db_mysql [km_res.c:84]: db_mysql_get_columns(): allocate 16 bytes for RES_NAMES[2] at 0x7f57b1c7b540
13(27147) DEBUG: db_mysql [km_res.c:91]: db_mysql_get_columns(): RES_NAMES(0x7f57b1c7b540)[2]=[etag]
13(27147) DEBUG: db_mysql [km_res.c:135]: db_mysql_get_columns(): use DB1_STRING result type
13(27147) DEBUG: db_mysql [km_res.c:84]: db_mysql_get_columns(): allocate 16 bytes for RES_NAMES[3] at 0x7f57b1c7b5b8
13(27147) DEBUG: db_mysql [km_res.c:91]: db_mysql_get_columns(): RES_NAMES(0x7f57b1c7b5b8)[3]=[event]
13(27147) DEBUG: db_mysql [km_res.c:135]: db_mysql_get_columns(): use DB1_STRING result type
13(27147) DEBUG: db_mysql [km_dbase.c:399]: db_mysql_fetch_result(): no rows returned from the query
13(27147) DEBUG: presence [publish.c:116]: msg_presentity_clean(): found n= 0 expires messages
13(27147) DEBUG: <core> [db_res.c:79]: db_free_columns(): freeing 4 columns
13(27147) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[0] at 0x7f57b1c7b450
13(27147) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[1] at 0x7f57b1c7b4c8
13(27147) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[2] at 0x7f57b1c7b540
13(27147) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[3] at 0x7f57b1c7b5b8
13(27147) DEBUG: <core> [db_res.c:96]: db_free_columns(): freeing result names at 0x7f57b1c7b350
13(27147) DEBUG: <core> [db_res.c:101]: db_free_columns(): freeing result types at 0x7f57b1c7b3d8
13(27147) DEBUG: <core> [db_res.c:138]: db_free_result(): freeing result set at 0x7f57b1cb3c38
13(27147) DEBUG: presence [subscribe.c:755]: msg_watchers_clean(): cleaning pending subscriptions
13(27147) DEBUG: presence [subscribe.c:2499]: timer_db_update(): db_update timer
13(27147) DEBUG: presence [subscribe.c:2222]: update_db_subs_timer(): update_db_subs_timer: start
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(27147) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(27147) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 69028787
13(27147) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 69028787
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
13(27147) DEBUG: dispatcher [dispatch.c:2700]: ds_check_timer(): no destination sets
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(27147) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(27147) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 69028797
13(27147) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 69028797
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
13(27147) DEBUG: presence [subscribe.c:2499]: timer_db_update(): db_update timer
13(27147) DEBUG: presence [subscribe.c:2222]: update_db_subs_timer(): update_db_subs_timer: start
13(27147) DEBUG: dispatcher [dispatch.c:2700]: ds_check_timer(): no destination sets
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(27147) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(27147) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 69028807
13(27147) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 69028807
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
38(27189) DEBUG: cdp [peermanager.c:280]: peer_timer(): peer_timer(): Peer hss.tera-ims.in State 6
38(27189) DEBUG: cdp [diameter_msg.c:81]: AAABuildMsgBuffer(): AAABuildMsgBuffer(): len=68
38(27189) DEBUG: cdp [receiver.c:994]: peer_send_msg(): peer_send_msg(): Pipe push [0x7f57a7a593b0]
36(27187) DEBUG: cdp [receiver.c:751]: receive_loop(): select_recv(): There is something on the send pipe
36(27187) DEBUG: cdp [receiver.c:764]: receive_loop(): select_recv(): Send pipe says [0x7f57a7a593b0] 8
36(27187) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f57a7a593b0) 280
36(27187) DEBUG: cdp [receiver.c:574]: do_receive(): receive_loop(): [hss.tera-ims.in] Recv Version 1 Length 76
36(27187) DEBUG: cdp [receiver.c:1088]: receive_message(): receive_message(): [hss.tera-ims.in] Recv msg 280
36(27187) DEBUG: cdp [peerstatemachine.c:90]: sm_process(): sm_process(): Peer hss.tera-ims.in State I_Open Event I_Rcv_DWA
36(27187) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f57a7a5a350) 280
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
3(27135) DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
3(27135) DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg(): method: <REGISTER>
3(27135) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): uri: <sip:scscf.tera-ims.in>
3(27135) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): version: <SIP/2.0>
3(27135) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK17bd.10a050bc2802d68a1c24cc62ea1ff54a.1>; state=16
3(27135) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
3(27135) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
3(27135) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
3(27135) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK17bd.9ba6f95c15ad9279c9f278b20ea8dd8e.0>; state=16
3(27135) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
3(27135) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=78
3(27135) DEBUG: <core> [core/parser/msg_parser.c:504]: parse_headers(): this is the second via
3(27135) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
3(27135) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKf7c6e62df3a141c6>; state=16
3(27135) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
3(27135) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=78
3(27135) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
3(27135) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [24]; uri=[sip:5252 at tera-ims.in]
3(27135) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:5252 at tera-ims.in>
]
3(27135) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <48698> <REGISTER>
3(27135) DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - request - call-id: [2722461655-4273533943 at 192.168.12.31] - cseq: [48698 REGISTER]
3(27135) DEBUG: <core> [core/receive.c:234]: receive_msg(): preparing to run routing scripts...
3(27135) ERROR: <script>: Inside route{........}
3(27135) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=82ec062707c9d218-43f712c4
3(27135) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
3(27135) ERROR: <script>: REGISTER (sip:5252 at tera-ims.in (192.168.12.14:4060) to sip:5252 at tera-ims.in, 2722461655-4273533943 at 192.168.12.31)
3(27135) DEBUG: <script>: Mem: Total 67108864, Free 63426528 [1% used]
3(27135) DEBUG: maxfwd [mf_funcs.c:76]: is_maxfwd_present(): value = 68
3(27135) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0
3(27135) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
3(27135) DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1
3(27135) DEBUG: siputils [checks.c:120]: has_totag(): no totag
3(27135) DEBUG: <core> [core/select.c:412]: run_select(): Calling SELECT 0x7f57b1c1a310
3(27135) DEBUG: tm [t_lookup.c:1001]: t_check_msg(): msg (0x7f57b1ce2dc0) id=1 global id=0 T start=0xffffffffffffffff
3(27135) DEBUG: tm [t_lookup.c:459]: t_lookup_request(): start searching: hash=56177, isACK=0
3(27135) DEBUG: tm [t_lookup.c:417]: matching_3261(): RFC3261 transaction matching failed
3(27135) DEBUG: tm [t_lookup.c:641]: t_lookup_request(): no transaction found
3(27135) DEBUG: tm [t_lookup.c:1070]: t_check_msg(): msg (0x7f57b1ce2dc0) id=1 global id=1 T end=(nil)
3(27135) DEBUG: pv [pv_core.c:1262]: pv_get_authattr(): no [Proxy-]Authorization header
3(27135) ERROR: <script>: ALGORITHM IS [<null>] and User-Agent is [F612/V6.0.10P1T5]
3(27135) DEBUG: pv [pv_core.c:1262]: pv_get_authattr(): no [Proxy-]Authorization header
3(27135) DEBUG: pv [pv_core.c:1262]: pv_get_authattr(): no [Proxy-]Authorization header
3(27135) DEBUG: ims_auth [authorize.c:734]: authenticate(): Running authenticate, is_proxy_auth=0
3(27135) DEBUG: ims_auth [authorize.c:754]: authenticate(): Checking if REGISTER is authorized for realm [tera-ims.in]...
3(27135) DEBUG: ims_auth [authorize.c:792]: authenticate(): Nonce or response missing: nonce len [1870209134], response16 len[1869180009]
3(27135) DEBUG: <script>: About to challenge! auth_ims
3(27135) DEBUG: ims_auth [authorize.c:299]: challenge(): Looking for route block [REG_MAR_REPLY]
3(27135) INFO: ims_auth [cxdx_mar.c:79]: create_return_code(): created AVP successfully : [maa_return_code] - [-2]
3(27135) DEBUG: ims_auth [authorize.c:323]: challenge(): Need to challenge for realm [tera-ims.in]
3(27135) DEBUG: ims_auth [authorize.c:330]: challenge(): Checking if REGISTER is authorized for realm [tera-ims.in]...
3(27135) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:5252 at tera-ims.in (Hash 571)
3(27135) DEBUG: tm [t_lookup.c:1302]: t_newtran(): msg id=1 , global msg id=1 , T on entrance=(nil)
3(27135) DEBUG: tm [t_lookup.c:459]: t_lookup_request(): start searching: hash=56177, isACK=0
3(27135) DEBUG: tm [t_lookup.c:417]: matching_3261(): RFC3261 transaction matching failed
3(27135) DEBUG: tm [t_lookup.c:641]: t_lookup_request(): no transaction found
3(27135) DEBUG: tm [t_hooks.c:349]: run_reqin_callbacks_internal(): trans=0x7f57a7a5a518, callback type 1, id 0 entered
3(27135) DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 calculated: bbefbe96323bc1dba4e7d44333a2183d
3(27135) DEBUG: ims_auth [authorize.c:466]: challenge(): Suspending SIP TM transaction
3(27135) DEBUG: ims_auth [authorize.c:1534]: multimedia_auth_request(): Sending MAR
3(27135) DEBUG: cdp [session.c:285]: cdp_add_session(): adding a session with id scscf.tera-ims.in;217154349;1
3(27135) DEBUG: cdp [session.c:306]: cdp_get_session(): called get session with id scscf.tera-ims.in;217154349;1 and hash 32
3(27135) DEBUG: cdp [session.c:315]: cdp_get_session(): no session found
3(27135) DEBUG: cdp [routing.c:202]: get_routing_peer(): getting diameter routing peer for realm: [tera-ims.in]
3(27135) DEBUG: cdp [routing.c:271]: get_routing_peer(): no routing peer found, trying default route
3(27135) DEBUG: cdp [routing.c:129]: get_first_connected_route(): The peer hss.tera-ims.in state is opened
3(27135) DEBUG: cdp [routing.c:83]: peer_handles_application(): Checking if peer hss.tera-ims.in handles application 16777216 for vendord 10415
3(27135) DEBUG: cdp [routing.c:131]: get_first_connected_route(): The peer hss.tera-ims.in matches - will forward there
3(27135) DEBUG: cdp [routing.c:149]: get_first_connected_route(): peer [hss.tera-ims.in] was last used @ 0
3(27135) DEBUG: cdp [routing.c:162]: get_first_connected_route(): chosen peer [hss.tera-ims.in]
3(27135) DEBUG: cdp [diameter_comm.c:145]: AAASendMessage(): Found diameter peer [hss.tera-ims.in] from routing table
3(27135) DEBUG: cdp [peerstatemachine.c:90]: sm_process(): sm_process(): Peer hss.tera-ims.in State I_Open Event Send_Message
3(27135) DEBUG: cdp [peerstatemachine.c:1142]: Snd_Message(): Snd_Message called to peer [hss.tera-ims.in] for request with code 303
3(27135) DEBUG: cdp [session.c:306]: cdp_get_session(): called get session with id scscf.tera-ims.in;217154349;1 and hash 32
3(27135) DEBUG: cdp [session.c:315]: cdp_get_session(): no session found
3(27135) DEBUG: cdp [diameter_msg.c:81]: AAABuildMsgBuffer(): AAABuildMsgBuffer(): len=316
3(27135) DEBUG: cdp [receiver.c:994]: peer_send_msg(): peer_send_msg(): Pipe push [0x7f57a7a5a350]
3(27135) DEBUG: ims_auth [cxdx_mar.c:549]: cxdx_send_mar(): Successfully sent async diameter
36(27187) DEBUG: cdp [receiver.c:751]: receive_loop(): select_recv(): There is something on the send pipe
3(27135) DEBUG: <core> [core/receive.c:275]: receive_msg(): request-route executed in: 640 usec
36(27187) DEBUG: cdp [receiver.c:764]: receive_loop(): select_recv(): Send pipe says [0x7f57a7a5a350] 8
3(27135) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
3(27135) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
3(27135) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
3(27135) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
3(27135) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
3(27135) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
3(27135) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
3(27135) DEBUG: <core> [core/receive.c:364]: receive_msg(): cleaning up
36(27187) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f57a7a5a350) 303
36(27187) DEBUG: cdp [receiver.c:574]: do_receive(): receive_loop(): [hss.tera-ims.in] Recv Version 1 Length 328
36(27187) DEBUG: cdp [receiver.c:1088]: receive_message(): receive_message(): [hss.tera-ims.in] Recv msg 303
36(27187) DEBUG: cdp [peerstatemachine.c:90]: sm_process(): sm_process(): Peer hss.tera-ims.in State I_Open Event I_Rcv_Message
36(27187) DEBUG: cdp [session.c:306]: cdp_get_session(): called get session with id scscf.tera-ims.in;217154349;1 and hash 32
36(27187) DEBUG: cdp [session.c:315]: cdp_get_session(): no session found
19(27165) DEBUG: cdp [worker.c:343]: worker_process(): worker_process(): [0] got task Q(1/1)
19(27165) DEBUG: tm [t_lookup.c:1563]: t_lookup_ident(): transaction found
19(27165) DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
19(27165) DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg(): method: <REGISTER>
19(27165) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): uri: <sip:scscf.tera-ims.in>
19(27165) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): version: <SIP/2.0>
19(27165) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK17bd.10a050bc2802d68a1c24cc62ea1ff54a.1>; state=16
19(27165) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
19(27165) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
19(27165) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
19(27165) INFO: ims_auth [cxdx_avp.c:137]: cxdx_get_avp(): cxdx_get_experimental_result_code: Failed finding avp (avp_code = 297, vendor_id = 0)
19(27165) DEBUG: ims_auth [authorize.c:1565]: pack_challenge(): setting QOP str used is [, qop="auth,auth-int"]
19(27165) DEBUG: ims_auth [authorize.c:1567]: pack_challenge(): QOP str used is [, qop="auth,auth-int"]
19(27165) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK17bd.9ba6f95c15ad9279c9f278b20ea8dd8e.0>; state=16
19(27165) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
19(27165) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=ffffffffffffffff
19(27165) DEBUG: <core> [core/parser/msg_parser.c:504]: parse_headers(): this is the second via
19(27165) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
19(27165) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKf7c6e62df3a141c6>; state=16
19(27165) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
19(27165) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=ffffffffffffffff
19(27165) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
19(27165) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [24]; uri=[sip:5252 at tera-ims.in]
19(27165) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:5252 at tera-ims.in>
]
19(27165) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <48698> <REGISTER>
19(27165) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0
19(27165) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
19(27165) DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (192.168.12.14, 192.168.12.14, 1)
19(27165) DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers reset
19(27165) DEBUG: tm [t_reply.c:598]: _reply_light(): reply sent out. buf=0x7f57b1ce43d0: SIP/2.0 401 Unauthor..., shmem=0x7f57a7a5d978: SIP/2.0 401 Unauthor
19(27165) DEBUG: tm [t_reply.c:608]: _reply_light(): finished
19(27165) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:5252 at tera-ims.in (Hash 571)
19(27165) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
19(27165) DEBUG: ims_auth [authorize.c:1689]: add_auth_vector(): Adding auth_vector (status 1) for IMPU sip:5252 at tera-ims.in / IMPI 5252 at tera-ims.in (Hash 571)
19(27165) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f57a7a5a350) 303
19(27165) DEBUG: ims_auth [cxdx_mar.c:464]: async_cdp_callback(): DBG:UAR Async CDP callback: ... Done resuming transaction
19(27165) INFO: ims_auth [cxdx_mar.c:79]: create_return_code(): created AVP successfully : [maa_return_code] - [1]
19(27165) DEBUG: tm [t_lookup.c:1563]: t_lookup_ident(): transaction found
19(27165) DEBUG: <script>: maa_return code is 1
19(27165) DEBUG: <script>: MAR success - 401/407 response sent from module
19(27165) DEBUG: ims_auth [cxdx_mar.c:87]: free_saved_transaction_data(): Freeing saved transaction data: async
5(27138) DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
5(27138) DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg(): method: <REGISTER>
5(27138) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): uri: <sip:scscf.tera-ims.in>
5(27138) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): version: <SIP/2.0>
5(27138) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK07bd.a852943edb11068fafd9992539a3a160.0>; state=16
5(27138) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
5(27138) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
5(27138) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
5(27138) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK07bd.f072c52490068d427da4a8d139082181.0>; state=16
5(27138) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
5(27138) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=78
5(27138) DEBUG: <core> [core/parser/msg_parser.c:504]: parse_headers(): this is the second via
5(27138) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
5(27138) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKb2c151cab9b4b2a8>; state=16
5(27138) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
5(27138) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=78
5(27138) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
5(27138) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [24]; uri=[sip:5252 at tera-ims.in]
5(27138) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:5252 at tera-ims.in>
]
5(27138) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <48699> <REGISTER>
5(27138) DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - request - call-id: [2722461655-4273533943 at 192.168.12.31] - cseq: [48699 REGISTER]
5(27138) DEBUG: <core> [core/receive.c:234]: receive_msg(): preparing to run routing scripts...
5(27138) ERROR: <script>: Inside route{........}
5(27138) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=82ec062707c9d218-43f712c4
5(27138) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
5(27138) ERROR: <script>: REGISTER (sip:5252 at tera-ims.in (192.168.12.14:4060) to sip:5252 at tera-ims.in, 2722461655-4273533943 at 192.168.12.31)
5(27138) DEBUG: <script>: Mem: Total 67108864, Free 63412480 [1% used]
5(27138) DEBUG: maxfwd [mf_funcs.c:76]: is_maxfwd_present(): value = 68
5(27138) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0
5(27138) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
5(27138) DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1
5(27138) DEBUG: siputils [checks.c:120]: has_totag(): no totag
5(27138) DEBUG: <core> [core/select.c:412]: run_select(): Calling SELECT 0x7f57b1c1a310
5(27138) DEBUG: tm [t_lookup.c:1001]: t_check_msg(): msg (0x7f57b1ce2dc0) id=1 global id=0 T start=0xffffffffffffffff
5(27138) DEBUG: tm [t_lookup.c:459]: t_lookup_request(): start searching: hash=56176, isACK=0
5(27138) DEBUG: tm [t_lookup.c:417]: matching_3261(): RFC3261 transaction matching failed
5(27138) DEBUG: tm [t_lookup.c:641]: t_lookup_request(): no transaction found
5(27138) DEBUG: tm [t_lookup.c:1070]: t_check_msg(): msg (0x7f57b1ce2dc0) id=1 global id=1 T end=(nil)
5(27138) ERROR: <script>: ALGORITHM IS [MD5] and User-Agent is [F612/V6.0.10P1T5]
5(27138) DEBUG: ims_auth [authorize.c:734]: authenticate(): Running authenticate, is_proxy_auth=0
5(27138) DEBUG: ims_auth [authorize.c:754]: authenticate(): Checking if REGISTER is authorized for realm [tera-ims.in]...
5(27138) DEBUG: ims_auth [utils.c:168]: get_nonce_response(): Calling find_credentials with realm [tera-ims.in]
5(27138) DEBUG: ims_auth [utils.c:57]: ims_find_credentials(): Searching credentials in realm [tera-ims.in]
5(27138) DEBUG: ims_auth [utils.c:92]: ims_find_credentials(): *hook = 0x7f57b1ce4200
5(27138) DEBUG: ims_auth [utils.c:103]: ims_find_credentials(): Credential parsed successfully
5(27138) DEBUG: ims_auth [utils.c:106]: ims_find_credentials(): Comparing realm <tera-ims.in> and <tera-ims.in>
5(27138) DEBUG: ims_auth [utils.c:195]: get_nonce_response(): Found nonce response
5(27138) DEBUG: ims_auth [authorize.c:812]: authenticate(): Looking for auth vector based on IMPI: [5252 at tera-ims.in] and IMPU: [sip:5252 at tera-ims.in]
5(27138) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:5252 at tera-ims.in (Hash 571)
5(27138) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
5(27138) DEBUG: ims_auth [authorize.c:829]: authenticate(): look for a fresh vector for 5252 at tera-ims.in
5(27138) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:5252 at tera-ims.in (Hash 571)
5(27138) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
5(27138) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 1 and were looking for 1
5(27138) DEBUG: ims_auth [authorize.c:1072]: get_auth_vector(): Found result
5(27138) INFO: ims_auth [authorize.c:840]: authenticate(): uri=sip:tera-ims.in nonce=96a8ab09c5eb528d33e129e8536b36ba response=692c12c39f6c1a1f1edbeaad2fb2534f qop=auth nc=00000001 cnonce=b9d7ed7f hbody=
5(27138) DEBUG: ims_auth [authorize.c:865]: authenticate(): nc is 00000001, expected: 00000001
5(27138) DEBUG: ims_auth [rfc2617.c:144]: calc_response(): calc_response(_ha1=109f03fd36c82554901f57711f30a8ba, _nonce=96a8ab09c5eb528d33e129e8536b36ba, _nc=00000001,_cnonce=b9d7ed7f, _qop=auth, _auth_int=0,_method=REGISTER,_uri=sip:tera-ims.in,_hentity=)
5(27138) DEBUG: ims_auth [rfc2617.c:186]: calc_response(): H(A1) = 109f03fd36c82554901f57711f30a8ba, H(A2) = 46cbd36adfc34f06868bcaab8365a069, rspauth = 692c12c39f6c1a1f1edbeaad2fb2534f
5(27138) INFO: ims_auth [authorize.c:892]: authenticate(): UE said: 692c12c39f6c1a1f1edbeaad2fb2534f and we expect 692c12c39f6c1a1f1edbeaad2fb2534f ha1 109f03fd36c82554901f57711f30a8ba (REGISTER)
5(27138) DEBUG: ims_auth [authorize.c:927]: authenticate(): vector 0x7f57a7a5d8a8 successfully used 1 time(s)
5(27138) DEBUG: ims_auth [authorize.c:930]: authenticate(): vector 0x7f57a7a5d8a8 isn't fresh anymore, recycle it with a new nonce
5(27138) DEBUG: ims_auth [rfc2617.c:144]: calc_response(): calc_response(_ha1=109f03fd36c82554901f57711f30a8ba, _nonce=96a8ab09c5eb528d33e129e8536b36ba, _nc=00000001,_cnonce=b9d7ed7f, _qop=auth, _auth_int=0,_method=null,_uri=sip:tera-ims.in,_hentity=)
5(27138) DEBUG: ims_auth [rfc2617.c:186]: calc_response(): H(A1) = 109f03fd36c82554901f57711f30a8ba, H(A2) = 9693a11527b9587fe0da520eb9c19e7f, rspauth = 7ebe6bfa6b087d23b548143a0c57389a
5(27138) DEBUG: ims_auth [authorize.c:1663]: add_authinfo_resp_hdr(): authinfo hdr built: Authentication-Info: nextnonce="a3dc15ac2c8c9e4a4f9dd25403c891d3",qop=auth,rspauth="7ebe6bfa6b087d23b548143a0c57389a",cnonce="b9d7ed7f",nc=00000001
5(27138) DEBUG: ims_auth [authorize.c:1665]: add_authinfo_resp_hdr(): authinfo hdr added 5(27138) DEBUG: <script>: Auth succeeded
5(27138) DEBUG: ims_registrar_scscf [lookup.c:267]: impu_registered(): Looking for IMPU <sip:5252 at tera-ims.in>
5(27138) DEBUG: ims_registrar_scscf [lookup.c:286]: impu_registered(): 'sip:5252 at tera-ims.in' not found in usrloc
5(27138) ERROR: <script>: Not REGISTERED
5(27138) DEBUG: ims_registrar_scscf [save.c:1269]: save(): Looking for route block [PRE_REG_SAR_REPLY]
5(27138) DEBUG: <core> [ims_getters.c:706]: cscf_get_realm_from_uri(): cscf_get_realm_from_uri: realm <tera-ims.in>.
5(27138) DEBUG: ims_registrar_scscf [save.c:1326]: save(): preparing for SAR assignment for new REGISTRATION <sip:5252 at tera-ims.in>
5(27138) DEBUG: tm [t_lookup.c:1302]: t_newtran(): msg id=1 , global msg id=1 , T on entrance=(nil)
5(27138) DEBUG: tm [t_lookup.c:459]: t_lookup_request(): start searching: hash=56176, isACK=0
5(27138) DEBUG: tm [t_lookup.c:417]: matching_3261(): RFC3261 transaction matching failed
5(27138) DEBUG: tm [t_lookup.c:641]: t_lookup_request(): no transaction found
5(27138) DEBUG: tm [t_hooks.c:349]: run_reqin_callbacks_internal(): trans=0x7f57a7a5f3e0, callback type 1, id 0 entered
5(27138) DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 calculated: 783f3ddc2c08dff064c0be9ce1a3d476
5(27138) INFO: ims_registrar_scscf [cxdx_sar.c:84]: create_return_code(): created AVP successfully : [saa_return_code] - [-2]
5(27138) DEBUG: ims_registrar_scscf [save.c:1430]: save(): Suspending SIP TM transaction with index [0] and label [0]
5(27138) DEBUG: cdp [session.c:285]: cdp_add_session(): adding a session with id scscf.tera-ims.in;217154349;2
5(27138) DEBUG: tm [t_lookup.c:1001]: t_check_msg(): msg (0x7f57b1ce2dc0) id=1 global id=1 T start=0x7f57a7a5f3e0
5(27138) DEBUG: tm [t_lookup.c:1073]: t_check_msg(): T (0x7f57a7a5f3e0) already found for msg (0x7f57b1ce2dc0)!
5(27138) DEBUG: cdp [session.c:306]: cdp_get_session(): called get session with id scscf.tera-ims.in;217154349;2 and hash 29
5(27138) DEBUG: cdp [session.c:315]: cdp_get_session(): no session found
5(27138) DEBUG: cdp [routing.c:202]: get_routing_peer(): getting diameter routing peer for realm: [tera-ims.in]
5(27138) DEBUG: cdp [routing.c:271]: get_routing_peer(): no routing peer found, trying default route
5(27138) DEBUG: cdp [routing.c:129]: get_first_connected_route(): The peer hss.tera-ims.in state is opened
5(27138) DEBUG: cdp [routing.c:83]: peer_handles_application(): Checking if peer hss.tera-ims.in handles application 16777216 for vendord 10415
5(27138) DEBUG: cdp [routing.c:131]: get_first_connected_route(): The peer hss.tera-ims.in matches - will forward there
5(27138) DEBUG: cdp [routing.c:149]: get_first_connected_route(): peer [hss.tera-ims.in] was last used @ 1539146670531724
5(27138) DEBUG: cdp [routing.c:162]: get_first_connected_route(): chosen peer [hss.tera-ims.in]
5(27138) DEBUG: cdp [diameter_comm.c:145]: AAASendMessage(): Found diameter peer [hss.tera-ims.in] from routing table
5(27138) DEBUG: cdp [peerstatemachine.c:90]: sm_process(): sm_process(): Peer hss.tera-ims.in State I_Open Event Send_Message
5(27138) DEBUG: cdp [peerstatemachine.c:1142]: Snd_Message(): Snd_Message called to peer [hss.tera-ims.in] for request with code 301
5(27138) DEBUG: cdp [session.c:306]: cdp_get_session(): called get session with id scscf.tera-ims.in;217154349;2 and hash 29
5(27138) DEBUG: cdp [session.c:315]: cdp_get_session(): no session found
5(27138) DEBUG: cdp [diameter_msg.c:81]: AAABuildMsgBuffer(): AAABuildMsgBuffer(): len=344
5(27138) DEBUG: cdp [receiver.c:994]: peer_send_msg(): peer_send_msg(): Pipe push [0x7f57a7a5a350]
5(27138) DEBUG: <core> [core/receive.c:275]: receive_msg(): request-route executed in: 681 usec
5(27138) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
5(27138) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
5(27138) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
5(27138) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
5(27138) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
5(27138) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
5(27138) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
5(27138) DEBUG: <core> [core/receive.c:364]: receive_msg(): cleaning up
36(27187) DEBUG: cdp [receiver.c:751]: receive_loop(): select_recv(): There is something on the send pipe
36(27187) DEBUG: cdp [receiver.c:764]: receive_loop(): select_recv(): Send pipe says [0x7f57a7a5a350] 8
36(27187) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f57a7a5a350) 301
36(27187) DEBUG: cdp [receiver.c:574]: do_receive(): receive_loop(): [hss.tera-ims.in] Recv Version 1 Length 2340
36(27187) DEBUG: cdp [receiver.c:1088]: receive_message(): receive_message(): [hss.tera-ims.in] Recv msg 301
36(27187) DEBUG: cdp [peerstatemachine.c:90]: sm_process(): sm_process(): Peer hss.tera-ims.in State I_Open Event I_Rcv_Message
36(27187) DEBUG: cdp [session.c:306]: cdp_get_session(): called get session with id scscf.tera-ims.in;217154349;2 and hash 29
36(27187) DEBUG: cdp [session.c:315]: cdp_get_session(): no session found
20(27166) DEBUG: cdp [worker.c:343]: worker_process(): worker_process(): [1] got task Q(2/2)
20(27166) DEBUG: ims_registrar_scscf [cxdx_sar.c:142]: async_cdp_callback(): There is transaction data this must have been called from save or assign server unreg20(27166) DEBUG: tm [t_lookup.c:1563]: t_lookup_ident(): transaction found
20(27166) DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
20(27166) DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg(): method: <REGISTER>
20(27166) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): uri: <sip:scscf.tera-ims.in>
20(27166) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): version: <SIP/2.0>
20(27166) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK07bd.a852943edb11068fafd9992539a3a160.0>; state=16
20(27166) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
20(27166) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
20(27166) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
20(27166) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK07bd.f072c52490068d427da4a8d139082181.0>; state=16
20(27166) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
20(27166) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=ffffffffffffffff
20(27166) DEBUG: <core> [core/parser/msg_parser.c:504]: parse_headers(): this is the second via
20(27166) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
20(27166) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKb2c151cab9b4b2a8>; state=16
20(27166) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
20(27166) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=ffffffffffffffff
20(27166) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
20(27166) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [24]; uri=[sip:5252 at tera-ims.in]
20(27166) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:5252 at tera-ims.in>
]
20(27166) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <48699> <REGISTER>
20(27166) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0
20(27166) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
20(27166) DEBUG: ims_registrar_scscf [cxdx_sar.c:189]: async_cdp_callback(): callid for found transaction is [2722461655-4273533943 at 192.168.12.31]
20(27166) INFO: ims_registrar_scscf [cxdx_avp.c:138]: cxdx_get_avp(): cxdx_get_experimental_result_code: Failed finding avp
20(27166) DEBUG: ims_registrar_scscf [cxdx_sar.c:214]: async_cdp_callback(): received AAA success for SAR - SAA
20(27166) DEBUG: ims_registrar_scscf [cxdx_sar.c:233]: async_cdp_callback(): Parsing user data string from SAA
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:727]: parse_service_profile(): child name is [PublicIdentity]
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:727]: parse_service_profile(): child name is [InitialFilterCriteria]
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:983]: print_user_data(): IMSSubscription:
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:986]: print_user_data(): Private Identity: <5252 at tera-ims.in>
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:988]: print_user_data(): Service Profile:
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:993]: print_user_data(): Public Identity: Barring [0] <sip:5252 at tera-ims.in>
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:999]: print_user_data(): Filter Criteria: Priority [0]ProfilePartInd [-1]
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1004]: print_user_data(): Trigger Point: CNF [ ] (_&_)|(_&_)
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1010]: print_user_data(): SPT: Grp[0] NOT[ ] RegType[0]
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1020]: print_user_data(): Method == <PUBLISH>
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1010]: print_user_data(): SPT: Grp[0] NOT[ ] RegType[0]
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1028]: print_user_data(): Hdr(Event(22)) == <.*presence.*>
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1010]: print_user_data(): SPT: Grp[0] NOT[ ] RegType[0]
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1032]: print_user_data(): SessionCase [0]
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1010]: print_user_data(): SPT: Grp[1] NOT[ ] RegType[0]
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1020]: print_user_data(): Method == <PUBLISH>
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1010]: print_user_data(): SPT: Grp[1] NOT[ ] RegType[0]
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1028]: print_user_data(): Hdr(Event(22)) == <.*presence.*>
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1010]: print_user_data(): SPT: Grp[1] NOT[ ] RegType[0]
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1032]: print_user_data(): SessionCase [3]
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1010]: print_user_data(): SPT: Grp[2] NOT[ ] RegType[0]
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1020]: print_user_data(): Method == <SUBSCRIBE>
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1010]: print_user_data(): SPT: Grp[2] NOT[ ] RegType[0]
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1028]: print_user_data(): Hdr(Event(22)) == <.*presence.*>
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1010]: print_user_data(): SPT: Grp[2] NOT[ ] RegType[0]
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1032]: print_user_data(): SessionCase [1]
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1010]: print_user_data(): SPT: Grp[3] NOT[ ] RegType[0]
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1020]: print_user_data(): Method == <SUBSCRIBE>
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1010]: print_user_data(): SPT: Grp[3] NOT[ ] RegType[0]
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1028]: print_user_data(): Hdr(Event(22)) == <.*presence.*>
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1010]: print_user_data(): SPT: Grp[3] NOT[ ] RegType[0]
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1032]: print_user_data(): SessionCase [2]
20(27166) DEBUG: ims_registrar_scscf [userdata_parser.c:1049]: print_user_data(): AS: <sip:192.168.12.14:5065> Handling [0] SrvInfo: <>
20(27166) DEBUG: ims_registrar_scscf [cxdx_sar.c:240]: async_cdp_callback(): Successfully parse user data XML setting ref to 1 (we are referencing it)
20(27166) DEBUG: ims_registrar_scscf [save.c:790]: update_contacts(): updating contacts in REGISTRATION state
20(27166) DEBUG: ims_usrloc_scscf [impurecord.c:943]: update_impurecord(): No subscription yet for [5252 at tera-ims.in]... adding
20(27166) DEBUG: ims_usrloc_scscf [impurecord.c:1273]: ref_subscription_unsafe(): Reffing subscription [5252 at tera-ims.in] - was [1]
20(27166) DEBUG: ims_usrloc_scscf [impurecord.c:971]: update_impurecord(): No existing impu record for <sip:5252 at tera-ims.in>.... creating new one
20(27166) DEBUG: ims_usrloc_scscf [impurecord.c:1273]: ref_subscription_unsafe(): Reffing subscription [5252 at tera-ims.in] - was [2]
20(27166) DEBUG: ims_usrloc_scscf [udomain.c:238]: mem_insert_impurecord(): inserted new impurecord into memory [sip:5252 at tera-ims.in]
20(27166) DEBUG: ims_usrloc_scscf [usrloc_db.c:157]: db_insert_impurecord(): DB: Inserting/Updating IMPU [sip:5252 at tera-ims.in]
20(27166) DEBUG: ims_usrloc_scscf [ul_callback.h:120]: run_ul_callbacks(): impurecord=0x7f57a7a5ef28, contact=(nil), callback type 256/256, id 0 entered
20(27166) DEBUG: ims_registrar_scscf [usrloc_cb.c:53]: ul_impu_inserted(): Received notification of UL IMPU insert for IMPU <sip:5252 at tera-ims.in>20(27166) DEBUG: ims_registrar_scscf [usrloc_cb.c:55]: ul_impu_inserted(): Registering for callbacks on this IMPU for contact insert, update, delete or expire to send notifications if there are any subscriptions20(27166) DEBUG: ims_usrloc_scscf [ul_callback.c:168]: register_ulcb(): installing callback for SCSCF IMPU record with type [1024]
20(27166) DEBUG: ims_usrloc_scscf [ul_callback.c:168]: register_ulcb(): installing callback for SCSCF IMPU record with type [30720]
20(27166) DEBUG: ims_registrar_scscf [usrloc_cb.c:59]: ul_impu_inserted(): Selectively asking for expire or no contact delete callbacks only on the anchor of the implicit set so that we only send one SAR per implicit set20(27166) DEBUG: ims_usrloc_scscf [ul_callback.c:168]: register_ulcb(): installing callback for SCSCF IMPU record with type [80]
20(27166) DEBUG: ims_usrloc_scscf [impurecord.c:1284]: unref_subscription_unsafe(): un-reffing subscription [5252 at tera-ims.in] - was [3]
20(27166) DEBUG: ims_registrar_scscf [save.c:519]: update_contacts_helper(): updating the contacts for IMPU <sip:5252 at tera-ims.in>
20(27166) DEBUG: <core> [ims_getters.c:784]: cscf_get_sos_uri_param(): cscf_get_sos_uri_param: searching through the uri parameters:alias=192.168.12.31~5060~1
20(27166) DEBUG: <core> [ims_getters.c:795]: cscf_get_sos_uri_param(): cscf_get_sos_uri_param:name: alias body: 192.168.12.31~5060~1
20(27166) DEBUG: ims_registrar_scscf [save.c:137]: calc_contact_expires(): Calculated expires for contact is 60
20(27166) DEBUG: ims_registrar_scscf [save.c:548]: update_contacts_helper(): Need to update contact: <sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1>: q_value [-1],sos: [0],expires [60]
20(27166) DEBUG: ims_registrar_scscf [save.c:550]: update_contacts_helper(): packing contact information
20(27166) DEBUG: ims_registrar_scscf [save.c:556]: update_contacts_helper(): adding/updating contact based on prior existence
20(27166) DEBUG: ims_usrloc_scscf [impurecord.c:748]: get_scontact(): looking for contact [sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1] in slot 196
20(27166) DEBUG: ims_registrar_scscf [save.c:562]: update_contacts_helper(): inserting new contact
20(27166) DEBUG: ims_usrloc_scscf [impurecord.c:562]: insert_scontact(): INSERTing ucontact in usrloc module
20(27166) DEBUG: ims_usrloc_scscf [ucontact.c:173]: new_ucontact(): generating hash based on [sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1]
20(27166) DEBUG: ims_usrloc_scscf [impurecord.c:280]: mem_insert_scontact(): Created new contact in memory with AOR: [sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1] and hash [196]
20(27166) DEBUG: ims_usrloc_scscf [usrloc_db.c:289]: db_insert_ucontact(): DB: inserting ucontact [sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1]
20(27166) DEBUG: ims_usrloc_scscf [usrloc_db.c:311]: db_insert_ucontact(): Converted params to string to insert into db: []
20(27166) DEBUG: ims_usrloc_scscf [udomain.c:843]: ref_contact_unsafe(): incrementing ref count on contact [sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1], was 1
20(27166) DEBUG: ims_usrloc_scscf [impurecord.c:1225]: link_contact_to_impu(): number of contacts for IMPU [sip:5252 at tera-ims.in] is 1
20(27166) DEBUG: ims_usrloc_scscf [usrloc_db.c:1065]: db_link_contact_to_impu(): DB: linking contact to IMPU
20(27166) DEBUG: ims_usrloc_scscf [usrloc_db.c:1084]: db_link_contact_to_impu(): QUERY IS [] and len is 0
20(27166) ERROR: db_mysql [km_dbase.c:128]: db_mysql_submit_query(): driver error on query: Query was empty (1065)
20(27166) ERROR: <core> [db_query.c:181]: db_do_raw_query(): error while submitting query
20(27166) ERROR: ims_usrloc_scscf [usrloc_db.c:1086]: db_link_contact_to_impu(): Unable to link impu-contact in DB - impu [sip:5252 at tera-ims.in], contact [sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1]
20(27166) ERROR: ims_usrloc_scscf [impurecord.c:1227]: link_contact_to_impu(): Failed to update DB linking contact [sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1] to IMPU [sip:5252 at tera-ims.in]...continuing but db will be out of sync!
20(27166) DEBUG: ims_usrloc_scscf [udomain.c:852]: unref_contact_unsafe(): decrementing ref count on contact [sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1], was 2
20(27166) DEBUG: ims_usrloc_scscf [ul_callback.h:120]: run_ul_callbacks(): impurecord=0x7f57a7a5ef28, contact=0x7f57a7a62308, callback type 1024/1024, id 0 entered
20(27166) DEBUG: ims_registrar_scscf [usrloc_cb.c:88]: ul_contact_changed(): Received notification of type 1024 on contact Address <sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1>20(27166) DEBUG: ims_registrar_scscf [usrloc_cb.c:91]: ul_contact_changed(): There are no subscriptions for this IMPU therefore breaking out now as nothing to do20(27166) DEBUG: ims_registrar_scscf [reply.c:541]: build_contact(): created Contact HF: Contact: <sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1>;expires=54
20(27166) DEBUG: ims_registrar_scscf [reply.c:584]: build_p_associated_uri(): Building P-Associated-URI
20(27166) DEBUG: ims_registrar_scscf [reply.c:633]: build_p_associated_uri(): Created P-Associated-URI HF P-Associated-URI: <sip:5252 at tera-ims.in>
20(27166) DEBUG: ims_registrar_scscf [registrar_notify.c:450]: event_reg(): Sending Reg event notifies
20(27166) DEBUG: ims_registrar_scscf [registrar_notify.c:451]: event_reg(): Switching on event type: 720(27166) DEBUG: ims_usrloc_scscf [udomain.c:690]: get_impus_from_subscription_as_string(): getting IMPU subscription set
20(27166) DEBUG: ims_usrloc_scscf [udomain.c:707]: get_impus_from_subscription_as_string(): Got Record sip:5252 at tera-ims.in (20)
20(27166) DEBUG: ims_usrloc_scscf [udomain.c:722]: get_impus_from_subscription_as_string(): num of records returned is 1 and we need 20 bytes
20(27166) DEBUG: ims_registrar_scscf [registrar_notify.c:522]: event_reg(): About to create notification20(27166) DEBUG: ims_registrar_scscf [registrar_notify.c:1397]: create_notifications(): Creating notification20(27166) DEBUG: ims_registrar_scscf [registrar_notify.c:1400]: create_notifications(): r_passed and c_passed are valid and presentity uri and watcher_contact is 0 - this must be a ul callback no need to lock domain20(27166) DEBUG: ims_registrar_scscf [cxdx_sar.c:259]: async_cdp_callback(): Updated contacts: Contact: <sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1>;expires=54
20(27166) DEBUG: ims_registrar_scscf [reply.c:648]: reg_send_reply_transactional(): Contacts: Contact: <sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1>;expires=54
20(27166) DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (192.168.12.14, 192.168.12.14, 1)
20(27166) DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers reset
20(27166) DEBUG: tm [t_reply.c:598]: _reply_light(): reply sent out. buf=0x7f57b1ce4970: SIP/2.0 200 OK
Via:..., shmem=0x7f57a7a62a58: SIP/2.0 200 OK
Via:
20(27166) DEBUG: tm [t_reply.c:608]: _reply_light(): finished
20(27166) DEBUG: ims_registrar_scscf [cxdx_sar.c:272]: async_cdp_callback(): DBG:SAR Async CDP callback: ... Done resuming transaction
20(27166) INFO: ims_registrar_scscf [cxdx_sar.c:84]: create_return_code(): created AVP successfully : [saa_return_code] - [1]
20(27166) DEBUG: ims_usrloc_scscf [impurecord.c:1284]: unref_subscription_unsafe(): un-reffing subscription [5252 at tera-ims.in] - was [2]
20(27166) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f57a7a5a350) 301
20(27166) DEBUG: tm [t_lookup.c:1563]: t_lookup_ident(): transaction found
20(27166) DEBUG: <script>: saa_return code is 1
20(27166) DEBUG: <script>: saa_return code (for scscf_save on register) is 1
20(27166) DEBUG: <script>: SAR success - 200 response sent from module
20(27166) DEBUG: ims_isc [ims_isc_mod.c:428]: isc_match_filter_reg(): Checking triggers
20(27166) DEBUG: ims_isc [ims_isc_mod.c:432]: isc_match_filter_reg(): Starting triggering
20(27166) DEBUG: <core> [ims_getters.c:1099]: cscf_get_originating_user(): DEBUG:cscf_get_originating_user: From sip:5252 at tera-ims.in
20(27166) DEBUG: ims_isc [ims_isc_mod.c:446]: isc_match_filter_reg(): Orig User before clean: <sip:5252 at tera-ims.in> [0]
20(27166) DEBUG: ims_isc [ims_isc_mod.c:448]: isc_match_filter_reg(): Orig User after clean: <sip:5252 at tera-ims.in> [0]
20(27166) DEBUG: ims_isc [checker.c:383]: isc_checker_find(): isc_checker_find: starting search
20(27166) DEBUG: ims_isc [checker.c:405]: isc_checker_find(): isc_checker_find(): got a r_public for the user sip:5252 at tera-ims.in
20(27166) DEBUG: ims_isc [checker.c:421]: isc_checker_find(): About to try p->s->service_profiles_cnt!! #profiles is 1
20(27166) DEBUG: ims_isc [checker.c:423]: isc_checker_find(): About to try p->s->service_profiles[a].filter_criterai_cnt
20(27166) DEBUG: ims_isc [checker.c:434]: isc_checker_find(): DEBUG ISC: SECOND TIME About to try p->s->service_profiles_cnt!!
20(27166) DEBUG: ims_isc [checker.c:438]: isc_checker_find(): DEBUG ISC : About to try p->s->service_profiles
20(27166) DEBUG: ims_isc [checker.c:441]: isc_checker_find(): DEBUG ISC : About to try public identities
20(27166) DEBUG: ims_isc [checker.c:444]: isc_checker_find(): DEBUG ISC : About to try WPSI
20(27166) DEBUG: ims_isc [checker.c:286]: isc_check_filter_criteria(): ifc_checker_trigger: Starting expression check:
20(27166) DEBUG: ims_isc [checker.c:206]: isc_check_spt(): ifc_check_spt: SPT type 2 -> Method == PUBLISH ?
20(27166) DEBUG: ims_isc [checker.c:208]: isc_check_spt(): ifc_check_spt: Found method REGISTER
20(27166) DEBUG: ims_isc [checker.c:307]: isc_check_filter_criteria(): ifc_checker_trigger: - group compromised, skipping to next group
20(27166) DEBUG: ims_isc [checker.c:206]: isc_check_spt(): ifc_check_spt: SPT type 2 -> Method == PUBLISH ?
20(27166) DEBUG: ims_isc [checker.c:208]: isc_check_spt(): ifc_check_spt: Found method REGISTER
20(27166) DEBUG: ims_isc [checker.c:300]: isc_check_filter_criteria(): ifc_checker_trigger: - group 1 => 0.
20(27166) DEBUG: ims_isc [checker.c:307]: isc_check_filter_criteria(): ifc_checker_trigger: - group compromised, skipping to next group
20(27166) DEBUG: ims_isc [checker.c:206]: isc_check_spt(): ifc_check_spt: SPT type 2 -> Method == SUBSCRIBE ?
20(27166) DEBUG: ims_isc [checker.c:208]: isc_check_spt(): ifc_check_spt: Found method REGISTER
20(27166) DEBUG: ims_isc [checker.c:300]: isc_check_filter_criteria(): ifc_checker_trigger: - group 2 => 0.
20(27166) DEBUG: ims_isc [checker.c:307]: isc_check_filter_criteria(): ifc_checker_trigger: - group compromised, skipping to next group
20(27166) DEBUG: ims_isc [checker.c:206]: isc_check_spt(): ifc_check_spt: SPT type 2 -> Method == SUBSCRIBE ?
20(27166) DEBUG: ims_isc [checker.c:208]: isc_check_spt(): ifc_check_spt: Found method REGISTER
20(27166) DEBUG: ims_isc [checker.c:300]: isc_check_filter_criteria(): ifc_checker_trigger: - group 3 => 0.
20(27166) DEBUG: ims_isc [checker.c:307]: isc_check_filter_criteria(): ifc_checker_trigger: - group compromised, skipping to next group
20(27166) DEBUG: ims_isc [checker.c:315]: isc_check_filter_criteria(): ifc_checker_trigger: Check finished => 0
20(27166) DEBUG: ims_isc [ims_isc_mod.c:460]: isc_match_filter_reg(): No REGISTER match found in filter criteria
20(27166) DEBUG: tm [t_reply.c:929]: free_faked_req(): removing hdr->parsed 14
6(27139) DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
6(27139) DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg(): method: <SUBSCRIBE>
6(27139) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): uri: <sip:5252 at tera-ims.in>
6(27139) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): version: <SIP/2.0>
6(27139) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK8dfb.538092e5fe1b9ccfd862e4555ed2763a.1>; state=16
6(27139) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
6(27139) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
6(27139) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
6(27139) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK8dfb.7cd62394000000000000000000000000.0>; state=16
6(27139) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
6(27139) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=78
6(27139) DEBUG: <core> [core/parser/msg_parser.c:504]: parse_headers(): this is the second via
6(27139) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
6(27139) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [24]; uri=[sip:5252 at tera-ims.in]
6(27139) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:5252 at tera-ims.in>
]
6(27139) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <10> <SUBSCRIBE>
6(27139) DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - request - call-id: [728c7ec248d1f6d2-27025 at 192.168.12.14] - cseq: [10 SUBSCRIBE]
6(27139) DEBUG: <core> [core/receive.c:234]: receive_msg(): preparing to run routing scripts...
6(27139) ERROR: <script>: Inside route{........}
6(27139) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=b73efefe53cbd90b898919c483e5f28e-1f24
6(27139) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
6(27139) ERROR: <script>: SUBSCRIBE (sip:pcscf.tera-ims.in (192.168.12.14:4060) to sip:5252 at tera-ims.in, 728c7ec248d1f6d2-27025 at 192.168.12.14)
6(27139) DEBUG: <script>: Mem: Total 67108864, Free 63393088 [1% used]
6(27139) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0
6(27139) DEBUG: maxfwd [mf_funcs.c:76]: is_maxfwd_present(): value = 69
6(27139) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
6(27139) DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1
6(27139) DEBUG: siputils [checks.c:120]: has_totag(): no totag
6(27139) DEBUG: <core> [core/select.c:412]: run_select(): Calling SELECT 0x7f57b1c1a310
6(27139) DEBUG: tm [t_lookup.c:1001]: t_check_msg(): msg (0x7f57b1ce2dc0) id=1 global id=0 T start=0xffffffffffffffff
6(27139) DEBUG: tm [t_lookup.c:459]: t_lookup_request(): start searching: hash=49112, isACK=0
6(27139) DEBUG: tm [t_lookup.c:417]: matching_3261(): RFC3261 transaction matching failed
6(27139) DEBUG: tm [t_lookup.c:641]: t_lookup_request(): no transaction found
6(27139) DEBUG: tm [t_lookup.c:1070]: t_check_msg(): msg (0x7f57b1ce2dc0) id=1 global id=1 T end=(nil)
6(27139) ERROR: <script>: SUBSCRIBE: time [Wed Oct 10 10:14:30 2018] routeURI (sip:scscf.tera-ims.in) method (SUBSCRIBE) r-uri (sip:5252 at tera-ims.in) domain (tera-ims.in) )
6(27139) ERROR: <script>: Before entering to SUBSCRIBE
6(27139) DEBUG: tm [t_lookup.c:1302]: t_newtran(): msg id=1 , global msg id=1 , T on entrance=(nil)
6(27139) DEBUG: tm [t_lookup.c:459]: t_lookup_request(): start searching: hash=49112, isACK=0
6(27139) DEBUG: tm [t_lookup.c:417]: matching_3261(): RFC3261 transaction matching failed
6(27139) DEBUG: tm [t_lookup.c:641]: t_lookup_request(): no transaction found
6(27139) DEBUG: tm [t_hooks.c:349]: run_reqin_callbacks_internal(): trans=0x7f57a7a62f80, callback type 1, id 0 entered
6(27139) DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 calculated: 8d04be46aa104e55316cc65387a2e75f
6(27139) DEBUG: siputils [checks.c:120]: has_totag(): no totag
6(27139) DEBUG: <script>: This is an initial SUBSCRIBE
6(27139) DEBUG: ims_registrar_scscf [lookup.c:381]: term_impu_registered(): term_impu_registered: Looking for <sip:5252 at tera-ims.in>
6(27139) DEBUG: ims_registrar_scscf [lookup.c:393]: term_impu_registered(): 'sip:5252 at tera-ims.in' found in usrloc
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:293]: can_subscribe_to_reg(): Checking if allowed to subscribe to event
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:338]: can_subscribe_to_reg(): Msg has no ttag - this is initial subscribe - get presentity URI from req URI
6(27139) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
6(27139) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:355]: can_subscribe_to_reg(): P-Asserted-Identity <sip:pcscf.tera-ims.in>.
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:357]: can_subscribe_to_reg(): Looking for IMPU in usrloc <sip:5252 at tera-ims.in>
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:368]: can_subscribe_to_reg(): <sip:5252 at tera-ims.in> found in usrloc
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:399]: can_subscribe_to_reg(): Did not find p-asserted-identity <sip:pcscf.tera-ims.in> in SP
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:408]: can_subscribe_to_reg(): Path: <<sip:term at pcscf.tera-ims.in;lr>>.
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:413]: can_subscribe_to_reg(): Identity found in Path <<sip:term at pcscf.tera-ims.in;lr>>
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1014]: subscribe_to_reg(): Saving SUBSCRIBE
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1066]: subscribe_to_reg(): Msg has no ttag - this is initial subscribe
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1069]: subscribe_to_reg(): Got to tag from sent response: [53f4d4fdca30a8a1b8f60ced3dd1ac56-fc25] 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1070]: subscribe_to_reg(): This is initial subscribe - get presentity URI from req URI
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1118]: subscribe_to_reg(): To header URI (watcher URI) <sip:pcscf.tera-ims.in>.
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1127]: subscribe_to_reg(): watcher Contact <sip:pcscf.tera-ims.in>.
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1146]: subscribe_to_reg(): expires is more than zero - SUBSCRIBE 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1157]: subscribe_to_reg(): Subscription expires time <1539150370> expiry length <3700>
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1159]: subscribe_to_reg(): Received a new subscription (expires > 0), checking to see of impurecord for presentity exists
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1169]: subscribe_to_reg(): Received impurecord for presentity being subscribed to [sip:5252 at tera-ims.in]
6(27139) DEBUG: ims_usrloc_scscf [subscribe.c:83]: get_subscriber(): Getting existing subscription to reg if it exists for watcher contact <sip:pcscf.tera-ims.in> and presentity uri <sip:5252 at tera-ims.in> 6(27139) DEBUG: ims_usrloc_scscf [subscribe.c:98]: get_subscriber(): Did not find subscription for watcher contact <sip:pcscf.tera-ims.in> and presentity_uri <sip:5252 at tera-ims.in> 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1173]: subscribe_to_reg(): this must be a new subscriber, lets add it
6(27139) DEBUG: ims_usrloc_scscf [subscribe.c:247]: add_subscriber(): Adding reg subscription to IMPU record 6(27139) DEBUG: ims_usrloc_scscf [subscribe.c:118]: new_subscriber(): Creating new subscription to reg 6(27139) DEBUG: ims_usrloc_scscf [subscribe.c:195]: new_subscriber(): Adding sub dialog hash info with call_id: <728c7ec248d1f6d2-27025 at 192.168.12.14> and ttag <53f4d4fdca30a8a1b8f60ced3dd1ac56-fc25> amd ftag <b73efefe53cbd90b898919c483e5f28e-1f24> and hash code <1> 6(27139) DEBUG: ims_usrloc_scscf [subscribe.c:291]: add_subscriber(): Adding new subscription to IMPU record list 6(27139) DEBUG: ims_usrloc_scscf [usrloc_db.c:394]: db_insert_subscriber(): DB: inserting subscriber [sip:5252 at tera-ims.in]
6(27139) DEBUG: ims_usrloc_scscf [usrloc_db.c:1206]: db_link_subscriber_to_impu(): DB: linking subscriber to IMPU
6(27139) DEBUG: ims_usrloc_scscf [usrloc_db.c:1230]: db_link_subscriber_to_impu(): QUERY IS [INSERT INTO impu_subscriber (impu_id, subscriber_id) (SELECT I.id, S.id FROM impu I, subscriber S WHERE I.impu='sip:5252 at tera-ims.in' and S.event='1' and S.watcher_contact='sip:pcscf.tera-ims.in' and S.presentity_uri='sip:5252 at tera-ims.in')] and len is 240
6(27139) DEBUG: <core> [db_res.c:120]: db_new_result(): allocate 56 bytes for result set at 0x7f57b1ce46c8
6(27139) DEBUG: ims_usrloc_scscf [usrloc_db.c:1235]: db_link_subscriber_to_impu(): Query success
6(27139) DEBUG: <core> [db_res.c:79]: db_free_columns(): freeing 0 columns
6(27139) DEBUG: <core> [db_res.c:138]: db_free_result(): freeing result set at 0x7f57b1ce46c8
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1217]: subscribe_to_reg(): Sending 200 OK to subscribing user 6(27139) DEBUG: tm [t_lookup.c:1001]: t_check_msg(): msg (0x7f57b1ce2dc0) id=1 global id=1 T start=0x7f57a7a62f80
6(27139) DEBUG: tm [t_lookup.c:1073]: t_check_msg(): T (0x7f57a7a62f80) already found for msg (0x7f57b1ce2dc0)!
6(27139) DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (192.168.12.14, 192.168.12.14, 1)
6(27139) DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers reset
6(27139) DEBUG: tm [t_reply.c:598]: _reply_light(): reply sent out. buf=0x7f57b1ce4b70: SIP/2.0 200 Subscrip..., shmem=0x7f57a7a5e488: SIP/2.0 200 Subscrip
6(27139) DEBUG: tm [t_reply.c:608]: _reply_light(): finished
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:450]: event_reg(): Sending Reg event notifies
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:451]: event_reg(): Switching on event type: 1 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:460]: event_reg(): Event type is IMS REGISTRAR SUBSCRIBE about to get reginfo_full 6(27139) DEBUG: ims_usrloc_scscf [udomain.c:690]: get_impus_from_subscription_as_string(): getting IMPU subscription set
6(27139) DEBUG: ims_usrloc_scscf [udomain.c:707]: get_impus_from_subscription_as_string(): Got Record sip:5252 at tera-ims.in (20)
6(27139) DEBUG: ims_usrloc_scscf [udomain.c:722]: get_impus_from_subscription_as_string(): num of records returned is 1 and we need 20 bytes
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:484]: event_reg(): About to ceate notification 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1397]: create_notifications(): Creating notification 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1404]: create_notifications(): This must be a cfg file subscribe need to lock domain and get impurecord 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1417]: create_notifications(): Scrolling through reg subscribers for this IMPU 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1420]: create_notifications(): Expires is greater than current time! 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1430]: create_notifications(): Subscription state: [active;expires=3700] 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1363]: contact_port_ip_match(): Matching contact using only port and ip - comparing [pcscf.tera-ims.in] and [pcscf.tera-ims.in]
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1442]: create_notifications(): This is a fix to ensure that we only send full reg info XML to the UE that just subscribed 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1443]: create_notifications(): about to make new notification! 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1445]: create_notifications(): we always increment the local cseq and version before we send a new notification
6(27139) DEBUG: ims_usrloc_scscf [subscribe.c:327]: update_subscriber(): No expires so will not update subscriber expires.
6(27139) DEBUG: ims_usrloc_scscf [subscribe.c:352]: update_subscriber(): Updating sub dialog hash info with call_id: <728c7ec248d1f6d2-27025 at 192.168.12.14> and ttag <53f4d4fdca30a8a1b8f60ced3dd1ac56-fc25> amd ftag <b73efefe53cbd90b898919c483e5f28e-1f24> and hash code <1> 6(27139) DEBUG: ims_usrloc_scscf [usrloc_db.c:394]: db_insert_subscriber(): DB: inserting subscriber [sip:5252 at tera-ims.in]
6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:2079]: new_notification(): Creating new notification 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:2098]: new_notification(): call id: [728c7ec248d1f6d2-27025 at 192.168.12.14] 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:2104]: new_notification(): from tag: [b73efefe53cbd90b898919c483e5f28e-1f24] 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:2110]: new_notification(): to tag: [53f4d4fdca30a8a1b8f60ced3dd1ac56-fc25] 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:2116]: new_notification(): watcher_uri: [sip:pcscf.tera-ims.in] 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:2122]: new_notification(): watcher_contact: [sip:pcscf.tera-ims.in] 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:2128]: new_notification(): record_route: [] 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:2134]: new_notification(): sockinfo_str: [udp:192.168.12.14:6060] 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:2140]: new_notification(): presentity_uri: [sip:5252 at tera-ims.in] 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:2146]: new_notification(): Notification subscription state: [active;expires=3700] 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:2152]: new_notification(): Notification content type: [application/reginfo+xml] 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1454]: create_notifications(): Notification exists - about to add it 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:2193]: add_notification(): Adding notification 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:2198]: add_notification(): Notification exists 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:2206]: add_notification(): Adding to notification list 6(27139) DEBUG: ims_registrar_scscf [registrar_notify.c:1226]: subscribe_to_reg(): success adding notification for reg events
41(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:2259]: notification_event_process(): About to send notification 6(27139) DEBUG: <script>: Subscribe to reg successful41(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:1959]: send_notification(): Have a notification to send for the following IMPUs using domain [location]
6(27139) DEBUG: <core> [core/receive.c:275]: receive_msg(): request-route executed in: 118763 usec
41(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:1679]: generate_reginfo_full(): Getting reginfo_full 6(27139) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
6(27139) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
6(27139) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
6(27139) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
41(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:1687]: generate_reginfo_full(): Scrolling through public identities, current one <sip:5252 at tera-ims.in> 6(27139) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
6(27139) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
6(27139) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
6(27139) DEBUG: <core> [core/receive.c:364]: receive_msg(): cleaning up
41(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:1709]: generate_reginfo_full(): Retrieved IMPU record41(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:1718]: generate_reginfo_full(): IMPU <sip:5252 at tera-ims.in> has another active contact <sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1> so will set its state to active
41(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:1730]: generate_reginfo_full(): IMPU has active contacts so putting in status active41(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:1738]: generate_reginfo_full(): Scrolling through contact for this IMPU41(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:1620]: process_xml_for_contact(): Appending contact address: <sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1>41(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:1775]: generate_reginfo_full(): Returned full reg-info: [<?xml version="1.0"?>
<reginfo xmlns="urn:ietf:params:xml:ns:reginfo" version="%d" state="full">
<registration aor="sip:5252 at tera-ims.in" id="0x7f57a7a5ef28" state="active">
<contact id="0x7f57a7a62308" state="active" event="registered" expires="60" q="0.000">
<uri>sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1</uri>
</contact>
</registration>
</reginfo>
]41(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:1978]: send_notification(): Notification content: [<?xml version="1.0"?>
<reginfo xmlns="urn:ietf:params:xml:ns:reginfo" version="2" state="full">
<registration aor="sip:5252 at tera-ims.in" id="0x7f57a7a5ef28" state="active">
<contact id="0x7f57a7a62308" state="active" event="registered" expires="60" q="0.000">
<uri>sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1</uri>
</contact>
</registration>
</reginfo>
]41(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:1979]: send_notification(): DBG:send_notification: NOTIFY about <sip:pcscf.tera-ims.in>
41(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:2284]: build_dlg_t_from_notification(): Building dlg_t structure41(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:2287]: build_dlg_t_from_notification(): local cseq 1241(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:2291]: build_dlg_t_from_notification(): call id 728c7ec248d1f6d2-27025 at 192.168.12.1441(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:2294]: build_dlg_t_from_notification(): ftag b73efefe53cbd90b898919c483e5f28e-1f2441(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:2298]: build_dlg_t_from_notification(): ttag 53f4d4fdca30a8a1b8f60ced3dd1ac56-fc2541(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:2302]: build_dlg_t_from_notification(): loc uri sip:5252 at tera-ims.in41(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:2305]: build_dlg_t_from_notification(): rem target sip:pcscf.tera-ims.in41(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:2308]: build_dlg_t_from_notification(): rem uri sip:pcscf.tera-ims.in41(27210) DEBUG: <core> [core/socket_info.c:564]: grep_sock_info(): checking if host==us: 13==13 && [192.168.12.14] == [192.168.12.14]
41(27210) DEBUG: <core> [core/socket_info.c:567]: grep_sock_info(): checking if port 6060 (advertise 0) matches port 6060
41(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:2027]: send_notification(): Notification content exists - about to send notification with subscription state: [active;expires=3700] content_type: [application/reginfo+xml] content: [<?xml version="1.0"?>
<reginfo xmlns="urn:ietf:params:xml:ns:reginfo" version="2" state="full">
<registration aor="sip:5252 at tera-ims.in" id="0x7f57a7a5ef28" state="active">
<contact id="0x7f57a7a62308" state="active" event="registered" expires="60" q="0.000">
<uri>sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1</uri>
</contact>
</registration>
</reginfo>
] : presentity_uri: [sip:5252 at tera-ims.in] watcher_uri: [sip:pcscf.tera-ims.in]41(27210) DEBUG: tm [uac.c:427]: t_uac_prepare(): next_hop=<sip:pcscf.tera-ims.in>
41(27210) DEBUG: <core> [core/dns_cache.c:542]: _dns_hash_find(): (_sip._udp.pcscf.tera-ims.in(27), 33), h=665
41(27210) DEBUG: <core> [core/resolve.c:937]: get_record(): skipping 1 NS (p=0xa8b452, end=0xa8b483)
41(27210) DEBUG: <core> [core/resolve.c:952]: get_record(): parsing 2 ARs (p=0xa8b463, end=0xa8b483)
41(27210) DEBUG: <core> [core/dns_cache.c:1748]: dns_get_related(): (0x7f57a7a5d798 (_sip._udp.pcscf.tera-ims.in, 33), 33, *0x7f57b1ce36e8) (0)
41(27210) DEBUG: <core> [core/dns_cache.c:847]: dns_cache_add_unsafe(): adding _sip._udp.pcscf.tera-ims.in(27) 33 (flags=0) at 665
41(27210) DEBUG: <core> [core/dns_cache.c:847]: dns_cache_add_unsafe(): adding pcscf.tera-ims.in(17) 1 (flags=0) at 541
41(27210) DEBUG: <core> [core/dns_cache.c:2348]: dns_srv_get_nxt_rr(): (0x7f57a7a5d798, 0, 0, 1104461055): selected 0/1 in grp. 0 (rand_w=0, rr=0x7f57a7a5d7f8 rd=0x7f57a7a5d810 p=0 w=0 rsum=0)
41(27210) DEBUG: <core> [core/dns_cache.c:542]: _dns_hash_find(): (pcscf.tera-ims.in(17), 1), h=541
41(27210) DEBUG: <core> [core/dns_cache.c:2957]: dns_a_resolve(): (pcscf.tera-ims.in, 0) returning 0
41(27210) DEBUG: <core> [core/dns_cache.c:3200]: dns_srv_resolve_ip(): ("_sip._udp.pcscf.tera-ims.in", 0, 0), ret=0, ip=192.168.12.14
41(27210) DEBUG: <core> [core/dns_cache.c:3296]: dns_srv_sip_resolve(): (pcscf.tera-ims.in, 0, 0), srv0, ret=0
41(27210) DEBUG: tm [uac.c:152]: dlg2hash(): hashid 49111
41(27210) DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
41(27210) DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg(): method: <NOTIFY>
41(27210) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): uri: <sip:pcscf.tera-ims.in>
41(27210) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): version: <SIP/2.0>
41(27210) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK7dfb.42483352000000000000000000000000.0>; state=16
41(27210) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
41(27210) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
41(27210) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
41(27210) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=b73efefe53cbd90b898919c483e5f28e-1f24
41(27210) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
41(27210) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [67]; uri=[sip:pcscf.tera-ims.in]
41(27210) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:pcscf.tera-ims.in>]
41(27210) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <13> <NOTIFY>
41(27210) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=373
41(27210) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
41(27210) DEBUG: tm [uac.c:632]: send_prepared_request_impl(): uac: 0x7f57a7a66018 branch: 0 to 192.168.12.14:5060
41(27210) DEBUG: ims_registrar_scscf [registrar_notify.c:2261]: notification_event_process(): About to free notification 1(27133) DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): SIP Reply (status):
1(27133) DEBUG: <core> [core/parser/msg_parser.c:612]: parse_msg(): version: <SIP/2.0>
1(27133) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): status: <200>
1(27133) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg(): reason: <OK - P-CSCF processed notification>
1(27133) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK7dfb.42483352000000000000000000000000.0>; state=16
1(27133) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
1(27133) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
1(27133) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
1(27133) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=b73efefe53cbd90b898919c483e5f28e-1f24
1(27133) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
1(27133) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [67]; uri=[sip:pcscf.tera-ims.in]
1(27133) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:pcscf.tera-ims.in>]
1(27133) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <13> <NOTIFY>
1(27133) DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - reply - call-id: [728c7ec248d1f6d2-27025 at 192.168.12.14] - cseq: [13 NOTIFY]
1(27133) DEBUG: tm [t_lookup.c:1001]: t_check_msg(): msg (0x7f57b1ce2dc0) id=1 global id=0 T start=0xffffffffffffffff
1(27133) DEBUG: tm [t_lookup.c:879]: t_reply_matching(): t_reply_matching: hash 49111 label 0 branch 0
1(27133) DEBUG: tm [t_lookup.c:933]: t_reply_matching(): reply (0x7f57b1ce2dc0) matched an active transaction (T=0x7f57a7a65e10)!
1(27133) DEBUG: tm [t_lookup.c:1070]: t_check_msg(): msg (0x7f57b1ce2dc0) id=1 global id=1 T end=0x7f57a7a65e10
1(27133) DEBUG: tm [t_reply.c:2200]: reply_received(): org. status uas=0, uac[0]=0 local=2 is_invite=0)
1(27133) DEBUG: tm [t_reply.c:1265]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200
1(27133) DEBUG: tm [t_reply.c:2074]: local_reply(): branch=0, save=0, winner=0
1(27133) DEBUG: tm [t_reply.c:2113]: local_reply(): local transaction completed 200/0 (totag retr: 0/1024)
1(27133) DEBUG: tm [t_hooks.c:258]: run_trans_callbacks_internal(): DBG: trans=0x7f57a7a65e10, callback type 1024, id 0 entered
1(27133) DEBUG: ims_registrar_scscf [registrar_notify.c:1928]: uac_request_cb(): received NOTIFY reply type [1024] and code [200]
1(27133) DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers reset
1(27133) DEBUG: <core> [core/receive.c:348]: receive_msg(): reply-route executed in: 96 usec
1(27133) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
1(27133) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
1(27133) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
1(27133) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
1(27133) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
1(27133) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
1(27133) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
1(27133) DEBUG: <core> [core/receive.c:364]: receive_msg(): cleaning up
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(27147) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(27147) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 69028817
13(27147) DEBUG: ims_auth [authorize.c:199]: reg_await_timer(): Slot 571 <5252 at tera-ims.in>
13(27147) DEBUG: ims_auth [authorize.c:204]: reg_await_timer(): .. AV 1 - 3 Exp 69029115 0x7f57a7a5d8a8
13(27147) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 69028817
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
14(27148) DEBUG: tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7f57a7a5a518 from timer.c:651
14(27148) DEBUG: tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7f57a7a5f3e0 from timer.c:651
14(27148) DEBUG: tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7f57a7a62f80 from timer.c:651
14(27148) DEBUG: tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7f57a7a65e10 from timer.c:651
14(27148) DEBUG: tm [h_table.c:204]: free_cell_helper(): branch 0 -> dns_h.srv (_sip._udp.pcscf.tera-ims.in) ref=2, dns_h.a (pcscf.tera-ims.in) ref=2
13(27147) DEBUG: dispatcher [dispatch.c:2700]: ds_check_timer(): no destination sets
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
13(27147) DEBUG: presence [subscribe.c:2499]: timer_db_update(): db_update timer
13(27147) DEBUG: presence [subscribe.c:2222]: update_db_subs_timer(): update_db_subs_timer: start
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(27147) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(27147) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 69028827
13(27147) DEBUG: ims_auth [authorize.c:199]: reg_await_timer(): Slot 571 <5252 at tera-ims.in>
13(27147) DEBUG: ims_auth [authorize.c:204]: reg_await_timer(): .. AV 1 - 3 Exp 69029115 0x7f57a7a5d8a8
13(27147) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 69028827
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
2(27134) DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
2(27134) DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg(): method: <OPTIONS>
2(27134) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): uri: <sip:tera-ims.in>
2(27134) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): version: <SIP/2.0>
2(27134) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK11b8.3d30f33a70ea88f34e3b37f5adafec1e.0>; state=16
2(27134) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
2(27134) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
2(27134) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
2(27134) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
2(27134) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK7b4551e46fb9b93f>; state=16
2(27134) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
2(27134) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=78
2(27134) DEBUG: <core> [core/parser/msg_parser.c:504]: parse_headers(): this is the second via
2(27134) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
2(27134) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [24]; uri=[sip:5252 at tera-ims.in]
2(27134) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:5252 at tera-ims.in>
]
2(27134) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <64525> <OPTIONS>
2(27134) DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - request - call-id: [4592115927-3595957307 at 192.168.12.31] - cseq: [64525 OPTIONS]
2(27134) DEBUG: <core> [core/receive.c:234]: receive_msg(): preparing to run routing scripts...
2(27134) ERROR: <script>: Inside route{........}
2(27134) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=4720fe37c2a8e4d5-46a7591f
2(27134) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
2(27134) ERROR: <script>: OPTIONS (sip:5252 at tera-ims.in (192.168.12.14:5060) to sip:5252 at tera-ims.in, 4592115927-3595957307 at 192.168.12.31)
2(27134) DEBUG: <script>: Mem: Total 67108864, Free 63416728 [1% used]
2(27134) DEBUG: maxfwd [mf_funcs.c:76]: is_maxfwd_present(): value = 69
2(27134) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0
2(27134) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
2(27134) DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1
2(27134) DEBUG: siputils [checks.c:120]: has_totag(): no totag
2(27134) DEBUG: <core> [core/select.c:412]: run_select(): Calling SELECT 0x7f57b1c1a310
2(27134) DEBUG: <core> [core/socket_info.c:564]: grep_sock_info(): checking if host==us: 11==13 && [tera-ims.in] == [192.168.12.14]
2(27134) DEBUG: <core> [core/socket_info.c:567]: grep_sock_info(): checking if port 6060 (advertise 0) matches port 5060
2(27134) DEBUG: sl [sl.c:282]: send_reply(): reply in stateless mode (sl)
2(27134) DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (192.168.12.14, 192.168.12.14, 1)
2(27134) DEBUG: <core> [core/receive.c:275]: receive_msg(): request-route executed in: 319 usec
2(27134) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2(27134) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2(27134) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2(27134) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2(27134) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2(27134) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2(27134) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
2(27134) DEBUG: <core> [core/receive.c:364]: receive_msg(): cleaning up
13(27147) DEBUG: dispatcher [dispatch.c:2700]: ds_check_timer(): no destination sets
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(27147) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(27147) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 69028837
13(27147) DEBUG: ims_auth [authorize.c:199]: reg_await_timer(): Slot 571 <5252 at tera-ims.in>
13(27147) DEBUG: ims_auth [authorize.c:204]: reg_await_timer(): .. AV 1 - 3 Exp 69029115 0x7f57a7a5d8a8
13(27147) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 69028837
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
7(27141) DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
7(27141) DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg(): method: <REGISTER>
7(27141) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): uri: <sip:scscf.tera-ims.in>
7(27141) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): version: <SIP/2.0>
7(27141) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK04cd.b03b3f6197881d09b98087cb391852e5.1>; state=16
7(27141) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
7(27141) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
7(27141) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
7(27141) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK04cd.28a2e00aa1cc451c45ee58f06d73e4df.0>; state=16
7(27141) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
7(27141) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=78
7(27141) DEBUG: <core> [core/parser/msg_parser.c:504]: parse_headers(): this is the second via
7(27141) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
7(27141) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKe9f8e6f9739597a0>; state=16
7(27141) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
7(27141) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=78
7(27141) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
7(27141) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [24]; uri=[sip:5252 at tera-ims.in]
7(27141) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:5252 at tera-ims.in>
]
7(27141) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <48700> <REGISTER>
7(27141) DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - request - call-id: [2722461655-4273533943 at 192.168.12.31] - cseq: [48700 REGISTER]
7(27141) DEBUG: <core> [core/receive.c:234]: receive_msg(): preparing to run routing scripts...
7(27141) ERROR: <script>: Inside route{........}
7(27141) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=9577edfa2399864f-94ea1412
7(27141) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
7(27141) ERROR: <script>: REGISTER (sip:5252 at tera-ims.in (192.168.12.14:4060) to sip:5252 at tera-ims.in, 2722461655-4273533943 at 192.168.12.31)
7(27141) DEBUG: <script>: Mem: Total 67108864, Free 63416728 [1% used]
7(27141) DEBUG: maxfwd [mf_funcs.c:76]: is_maxfwd_present(): value = 68
7(27141) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0
7(27141) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
7(27141) DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1
7(27141) DEBUG: siputils [checks.c:120]: has_totag(): no totag
7(27141) DEBUG: <core> [core/select.c:412]: run_select(): Calling SELECT 0x7f57b1c1a310
7(27141) DEBUG: tm [t_lookup.c:1001]: t_check_msg(): msg (0x7f57b1ce2dc0) id=1 global id=0 T start=0xffffffffffffffff
7(27141) DEBUG: tm [t_lookup.c:459]: t_lookup_request(): start searching: hash=56384, isACK=0
7(27141) DEBUG: tm [t_lookup.c:417]: matching_3261(): RFC3261 transaction matching failed
7(27141) DEBUG: tm [t_lookup.c:641]: t_lookup_request(): no transaction found
7(27141) DEBUG: tm [t_lookup.c:1070]: t_check_msg(): msg (0x7f57b1ce2dc0) id=1 global id=1 T end=(nil)
7(27141) DEBUG: pv [pv_core.c:1262]: pv_get_authattr(): no [Proxy-]Authorization header
7(27141) ERROR: <script>: ALGORITHM IS [<null>] and User-Agent is [F612/V6.0.10P1T5]
7(27141) DEBUG: pv [pv_core.c:1262]: pv_get_authattr(): no [Proxy-]Authorization header
7(27141) DEBUG: pv [pv_core.c:1262]: pv_get_authattr(): no [Proxy-]Authorization header
7(27141) DEBUG: ims_auth [authorize.c:734]: authenticate(): Running authenticate, is_proxy_auth=0
7(27141) DEBUG: ims_auth [authorize.c:754]: authenticate(): Checking if REGISTER is authorized for realm [tera-ims.in]...
7(27141) DEBUG: ims_auth [authorize.c:792]: authenticate(): Nonce or response missing: nonce len [1870209134], response16 len[1869180009]
7(27141) DEBUG: <script>: About to challenge! auth_ims
7(27141) DEBUG: ims_auth [authorize.c:299]: challenge(): Looking for route block [REG_MAR_REPLY]
7(27141) INFO: ims_auth [cxdx_mar.c:79]: create_return_code(): created AVP successfully : [maa_return_code] - [-2]
7(27141) DEBUG: ims_auth [authorize.c:323]: challenge(): Need to challenge for realm [tera-ims.in]
7(27141) DEBUG: ims_auth [authorize.c:330]: challenge(): Checking if REGISTER is authorized for realm [tera-ims.in]...
7(27141) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:5252 at tera-ims.in (Hash 571)
7(27141) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
7(27141) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 3 and were looking for 0
7(27141) DEBUG: tm [t_lookup.c:1302]: t_newtran(): msg id=1 , global msg id=1 , T on entrance=(nil)
7(27141) DEBUG: tm [t_lookup.c:459]: t_lookup_request(): start searching: hash=56384, isACK=0
7(27141) DEBUG: tm [t_lookup.c:417]: matching_3261(): RFC3261 transaction matching failed
7(27141) DEBUG: tm [t_lookup.c:641]: t_lookup_request(): no transaction found
7(27141) DEBUG: tm [t_hooks.c:349]: run_reqin_callbacks_internal(): trans=0x7f57a7a65e10, callback type 1, id 0 entered
7(27141) DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 calculated: 7b2eeaa58318ceafe1748d320fb6ea79
7(27141) DEBUG: ims_auth [authorize.c:466]: challenge(): Suspending SIP TM transaction
7(27141) DEBUG: ims_auth [authorize.c:1534]: multimedia_auth_request(): Sending MAR
7(27141) DEBUG: cdp [session.c:285]: cdp_add_session(): adding a session with id scscf.tera-ims.in;217154349;3
7(27141) DEBUG: cdp [session.c:306]: cdp_get_session(): called get session with id scscf.tera-ims.in;217154349;3 and hash 30
7(27141) DEBUG: cdp [session.c:315]: cdp_get_session(): no session found
7(27141) DEBUG: cdp [routing.c:202]: get_routing_peer(): getting diameter routing peer for realm: [tera-ims.in]
7(27141) DEBUG: cdp [routing.c:271]: get_routing_peer(): no routing peer found, trying default route
7(27141) DEBUG: cdp [routing.c:129]: get_first_connected_route(): The peer hss.tera-ims.in state is opened
7(27141) DEBUG: cdp [routing.c:83]: peer_handles_application(): Checking if peer hss.tera-ims.in handles application 16777216 for vendord 10415
7(27141) DEBUG: cdp [routing.c:131]: get_first_connected_route(): The peer hss.tera-ims.in matches - will forward there
7(27141) DEBUG: cdp [routing.c:149]: get_first_connected_route(): peer [hss.tera-ims.in] was last used @ 1539146670541364
7(27141) DEBUG: cdp [routing.c:162]: get_first_connected_route(): chosen peer [hss.tera-ims.in]
7(27141) DEBUG: cdp [diameter_comm.c:145]: AAASendMessage(): Found diameter peer [hss.tera-ims.in] from routing table
7(27141) DEBUG: cdp [peerstatemachine.c:90]: sm_process(): sm_process(): Peer hss.tera-ims.in State I_Open Event Send_Message
7(27141) DEBUG: cdp [peerstatemachine.c:1142]: Snd_Message(): Snd_Message called to peer [hss.tera-ims.in] for request with code 303
7(27141) DEBUG: cdp [session.c:306]: cdp_get_session(): called get session with id scscf.tera-ims.in;217154349;3 and hash 30
7(27141) DEBUG: cdp [session.c:315]: cdp_get_session(): no session found
7(27141) DEBUG: cdp [diameter_msg.c:81]: AAABuildMsgBuffer(): AAABuildMsgBuffer(): len=316
7(27141) DEBUG: cdp [receiver.c:994]: peer_send_msg(): peer_send_msg(): Pipe push [0x7f57a7a65bb8]
7(27141) DEBUG: ims_auth [cxdx_mar.c:549]: cxdx_send_mar(): Successfully sent async diameter
7(27141) DEBUG: <core> [core/receive.c:275]: receive_msg(): request-route executed in: 1123 usec
7(27141) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
7(27141) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
7(27141) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
7(27141) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
7(27141) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
7(27141) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
7(27141) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
7(27141) DEBUG: <core> [core/receive.c:364]: receive_msg(): cleaning up
36(27187) DEBUG: cdp [receiver.c:751]: receive_loop(): select_recv(): There is something on the send pipe
36(27187) DEBUG: cdp [receiver.c:764]: receive_loop(): select_recv(): Send pipe says [0x7f57a7a65bb8] 8
36(27187) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f57a7a65bb8) 303
36(27187) DEBUG: cdp [receiver.c:574]: do_receive(): receive_loop(): [hss.tera-ims.in] Recv Version 1 Length 328
36(27187) DEBUG: cdp [receiver.c:1088]: receive_message(): receive_message(): [hss.tera-ims.in] Recv msg 303
36(27187) DEBUG: cdp [peerstatemachine.c:90]: sm_process(): sm_process(): Peer hss.tera-ims.in State I_Open Event I_Rcv_Message
36(27187) DEBUG: cdp [session.c:306]: cdp_get_session(): called get session with id scscf.tera-ims.in;217154349;3 and hash 30
36(27187) DEBUG: cdp [session.c:315]: cdp_get_session(): no session found
30(27179) DEBUG: cdp [worker.c:343]: worker_process(): worker_process(): [11] got task Q(3/3)
30(27179) DEBUG: tm [t_lookup.c:1563]: t_lookup_ident(): transaction found
30(27179) DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
30(27179) DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg(): method: <REGISTER>
30(27179) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): uri: <sip:scscf.tera-ims.in>
30(27179) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): version: <SIP/2.0>
30(27179) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK04cd.b03b3f6197881d09b98087cb391852e5.1>; state=16
30(27179) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
30(27179) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
30(27179) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
30(27179) INFO: ims_auth [cxdx_avp.c:137]: cxdx_get_avp(): cxdx_get_experimental_result_code: Failed finding avp (avp_code = 297, vendor_id = 0)
30(27179) DEBUG: ims_auth [authorize.c:1565]: pack_challenge(): setting QOP str used is [, qop="auth,auth-int"]
30(27179) DEBUG: ims_auth [authorize.c:1567]: pack_challenge(): QOP str used is [, qop="auth,auth-int"]
30(27179) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK04cd.28a2e00aa1cc451c45ee58f06d73e4df.0>; state=16
30(27179) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
30(27179) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=ffffffffffffffff
30(27179) DEBUG: <core> [core/parser/msg_parser.c:504]: parse_headers(): this is the second via
30(27179) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
30(27179) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKe9f8e6f9739597a0>; state=16
30(27179) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
30(27179) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=ffffffffffffffff
30(27179) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
30(27179) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [24]; uri=[sip:5252 at tera-ims.in]
30(27179) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:5252 at tera-ims.in>
]
30(27179) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <48700> <REGISTER>
30(27179) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0
30(27179) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
30(27179) DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (192.168.12.14, 192.168.12.14, 1)
30(27179) DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers reset
30(27179) DEBUG: tm [t_reply.c:598]: _reply_light(): reply sent out. buf=0x7f57b1ce43d0: SIP/2.0 401 Unauthor..., shmem=0x7f57a7a62a58: SIP/2.0 401 Unauthor
30(27179) DEBUG: tm [t_reply.c:608]: _reply_light(): finished
30(27179) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:5252 at tera-ims.in (Hash 571)
30(27179) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
30(27179) DEBUG: ims_auth [authorize.c:1689]: add_auth_vector(): Adding auth_vector (status 1) for IMPU sip:5252 at tera-ims.in / IMPI 5252 at tera-ims.in (Hash 571)
30(27179) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f57a7a65bb8) 303
30(27179) DEBUG: ims_auth [cxdx_mar.c:464]: async_cdp_callback(): DBG:UAR Async CDP callback: ... Done resuming transaction
30(27179) INFO: ims_auth [cxdx_mar.c:79]: create_return_code(): created AVP successfully : [maa_return_code] - [1]
30(27179) DEBUG: tm [t_lookup.c:1563]: t_lookup_ident(): transaction found
30(27179) DEBUG: <script>: maa_return code is 1
30(27179) DEBUG: <script>: MAR success - 401/407 response sent from module
30(27179) DEBUG: ims_auth [cxdx_mar.c:87]: free_saved_transaction_data(): Freeing saved transaction data: async
4(27136) DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
4(27136) DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg(): method: <REGISTER>
4(27136) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): uri: <sip:scscf.tera-ims.in>
4(27136) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): version: <SIP/2.0>
4(27136) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK14cd.c01e4771e6f86dc08a04af6bac0dcd71.0>; state=16
4(27136) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
4(27136) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
4(27136) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
4(27136) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK14cd.7b42807438c37ed99c99b288ebf43a5a.0>; state=16
4(27136) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
4(27136) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=78
4(27136) DEBUG: <core> [core/parser/msg_parser.c:504]: parse_headers(): this is the second via
4(27136) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
4(27136) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK4a625e7e86ab68ed>; state=16
4(27136) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
4(27136) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=78
4(27136) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
4(27136) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [24]; uri=[sip:5252 at tera-ims.in]
4(27136) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:5252 at tera-ims.in>
]
4(27136) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <48701> <REGISTER>
4(27136) DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - request - call-id: [2722461655-4273533943 at 192.168.12.31] - cseq: [48701 REGISTER]
4(27136) DEBUG: <core> [core/receive.c:234]: receive_msg(): preparing to run routing scripts...
4(27136) ERROR: <script>: Inside route{........}
4(27136) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=9577edfa2399864f-94ea1412
4(27136) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
4(27136) ERROR: <script>: REGISTER (sip:5252 at tera-ims.in (192.168.12.14:4060) to sip:5252 at tera-ims.in, 2722461655-4273533943 at 192.168.12.31)
4(27136) DEBUG: <script>: Mem: Total 67108864, Free 63403136 [1% used]
4(27136) DEBUG: maxfwd [mf_funcs.c:76]: is_maxfwd_present(): value = 68
4(27136) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0
4(27136) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
4(27136) DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1
4(27136) DEBUG: siputils [checks.c:120]: has_totag(): no totag
4(27136) DEBUG: <core> [core/select.c:412]: run_select(): Calling SELECT 0x7f57b1c1a310
4(27136) DEBUG: tm [t_lookup.c:1001]: t_check_msg(): msg (0x7f57b1ce2dc0) id=1 global id=0 T start=0xffffffffffffffff
4(27136) DEBUG: tm [t_lookup.c:459]: t_lookup_request(): start searching: hash=56385, isACK=0
4(27136) DEBUG: tm [t_lookup.c:417]: matching_3261(): RFC3261 transaction matching failed
4(27136) DEBUG: tm [t_lookup.c:641]: t_lookup_request(): no transaction found
4(27136) DEBUG: tm [t_lookup.c:1070]: t_check_msg(): msg (0x7f57b1ce2dc0) id=1 global id=1 T end=(nil)
4(27136) ERROR: <script>: ALGORITHM IS [MD5] and User-Agent is [F612/V6.0.10P1T5]
4(27136) DEBUG: ims_auth [authorize.c:734]: authenticate(): Running authenticate, is_proxy_auth=0
4(27136) DEBUG: ims_auth [authorize.c:754]: authenticate(): Checking if REGISTER is authorized for realm [tera-ims.in]...
4(27136) DEBUG: ims_auth [utils.c:168]: get_nonce_response(): Calling find_credentials with realm [tera-ims.in]
4(27136) DEBUG: ims_auth [utils.c:57]: ims_find_credentials(): Searching credentials in realm [tera-ims.in]
4(27136) DEBUG: ims_auth [utils.c:92]: ims_find_credentials(): *hook = 0x7f57b1ce4200
4(27136) DEBUG: ims_auth [utils.c:103]: ims_find_credentials(): Credential parsed successfully
4(27136) DEBUG: ims_auth [utils.c:106]: ims_find_credentials(): Comparing realm <tera-ims.in> and <tera-ims.in>
4(27136) DEBUG: ims_auth [utils.c:195]: get_nonce_response(): Found nonce response
4(27136) DEBUG: ims_auth [authorize.c:812]: authenticate(): Looking for auth vector based on IMPI: [5252 at tera-ims.in] and IMPU: [sip:5252 at tera-ims.in]
4(27136) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:5252 at tera-ims.in (Hash 571)
4(27136) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
4(27136) DEBUG: ims_auth [authorize.c:820]: authenticate(): vector 0x7f57a7a5d8a8 is marked for deletion
4(27136) DEBUG: ims_auth [authorize.c:829]: authenticate(): look for a fresh vector for 5252 at tera-ims.in
4(27136) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:5252 at tera-ims.in (Hash 571)
4(27136) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
4(27136) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 1 and were looking for 1
4(27136) DEBUG: ims_auth [authorize.c:1072]: get_auth_vector(): Found result
4(27136) INFO: ims_auth [authorize.c:840]: authenticate(): uri=sip:tera-ims.in nonce=9a7bb327ae2c6bba634d0d9b4b6d59fe response=b02e048baa03243537af0ad0cb0711ce qop=auth nc=00000002 cnonce=a0d1ccf6 hbody=
4(27136) DEBUG: ims_auth [authorize.c:865]: authenticate(): nc is 00000002, expected: 00000001
4(27136) DEBUG: <script>: About to challenge! auth_ims
4(27136) DEBUG: ims_auth [authorize.c:299]: challenge(): Looking for route block [REG_MAR_REPLY]
4(27136) INFO: ims_auth [cxdx_mar.c:79]: create_return_code(): created AVP successfully : [maa_return_code] - [-2]
4(27136) DEBUG: ims_auth [authorize.c:323]: challenge(): Need to challenge for realm [tera-ims.in]
4(27136) DEBUG: ims_auth [authorize.c:330]: challenge(): Checking if REGISTER is authorized for realm [tera-ims.in]...
4(27136) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:5252 at tera-ims.in (Hash 571)
4(27136) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
4(27136) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 2 and were looking for 0
4(27136) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 2 and were looking for 0
4(27136) DEBUG: tm [t_lookup.c:1302]: t_newtran(): msg id=1 , global msg id=1 , T on entrance=(nil)
4(27136) DEBUG: tm [t_lookup.c:459]: t_lookup_request(): start searching: hash=56385, isACK=0
4(27136) DEBUG: tm [t_lookup.c:417]: matching_3261(): RFC3261 transaction matching failed
4(27136) DEBUG: tm [t_lookup.c:641]: t_lookup_request(): no transaction found
4(27136) DEBUG: tm [t_hooks.c:349]: run_reqin_callbacks_internal(): trans=0x7f57a7a5f3e0, callback type 1, id 0 entered
4(27136) DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 calculated: 597fd0438c6eb4ee11f4fd2fc3f7f2bb
4(27136) DEBUG: ims_auth [authorize.c:466]: challenge(): Suspending SIP TM transaction
4(27136) DEBUG: ims_auth [authorize.c:1534]: multimedia_auth_request(): Sending MAR
4(27136) DEBUG: cdp [session.c:285]: cdp_add_session(): adding a session with id scscf.tera-ims.in;217154349;4
4(27136) DEBUG: cdp [session.c:306]: cdp_get_session(): called get session with id scscf.tera-ims.in;217154349;4 and hash 27
4(27136) DEBUG: cdp [session.c:315]: cdp_get_session(): no session found
4(27136) DEBUG: cdp [routing.c:202]: get_routing_peer(): getting diameter routing peer for realm: [tera-ims.in]
4(27136) DEBUG: cdp [routing.c:271]: get_routing_peer(): no routing peer found, trying default route
4(27136) DEBUG: cdp [routing.c:129]: get_first_connected_route(): The peer hss.tera-ims.in state is opened
4(27136) DEBUG: cdp [routing.c:83]: peer_handles_application(): Checking if peer hss.tera-ims.in handles application 16777216 for vendord 10415
4(27136) DEBUG: cdp [routing.c:131]: get_first_connected_route(): The peer hss.tera-ims.in matches - will forward there
4(27136) DEBUG: cdp [routing.c:149]: get_first_connected_route(): peer [hss.tera-ims.in] was last used @ 1539146697704161
4(27136) DEBUG: cdp [routing.c:162]: get_first_connected_route(): chosen peer [hss.tera-ims.in]
4(27136) DEBUG: cdp [diameter_comm.c:145]: AAASendMessage(): Found diameter peer [hss.tera-ims.in] from routing table
4(27136) DEBUG: cdp [peerstatemachine.c:90]: sm_process(): sm_process(): Peer hss.tera-ims.in State I_Open Event Send_Message
4(27136) DEBUG: cdp [peerstatemachine.c:1142]: Snd_Message(): Snd_Message called to peer [hss.tera-ims.in] for request with code 303
4(27136) DEBUG: cdp [session.c:306]: cdp_get_session(): called get session with id scscf.tera-ims.in;217154349;4 and hash 27
4(27136) DEBUG: cdp [session.c:315]: cdp_get_session(): no session found
4(27136) DEBUG: cdp [diameter_msg.c:81]: AAABuildMsgBuffer(): AAABuildMsgBuffer(): len=316
4(27136) DEBUG: cdp [receiver.c:994]: peer_send_msg(): peer_send_msg(): Pipe push [0x7f57a7a65bb8]
4(27136) DEBUG: ims_auth [cxdx_mar.c:549]: cxdx_send_mar(): Successfully sent async diameter
4(27136) DEBUG: <core> [core/receive.c:275]: receive_msg(): request-route executed in: 828 usec
4(27136) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
4(27136) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
4(27136) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
4(27136) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
4(27136) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
4(27136) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
4(27136) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
4(27136) DEBUG: <core> [core/receive.c:364]: receive_msg(): cleaning up
36(27187) DEBUG: cdp [receiver.c:751]: receive_loop(): select_recv(): There is something on the send pipe
36(27187) DEBUG: cdp [receiver.c:764]: receive_loop(): select_recv(): Send pipe says [0x7f57a7a65bb8] 8
36(27187) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f57a7a65bb8) 303
36(27187) DEBUG: cdp [receiver.c:574]: do_receive(): receive_loop(): [hss.tera-ims.in] Recv Version 1 Length 328
36(27187) DEBUG: cdp [receiver.c:1088]: receive_message(): receive_message(): [hss.tera-ims.in] Recv msg 303
36(27187) DEBUG: cdp [peerstatemachine.c:90]: sm_process(): sm_process(): Peer hss.tera-ims.in State I_Open Event I_Rcv_Message
36(27187) DEBUG: cdp [session.c:306]: cdp_get_session(): called get session with id scscf.tera-ims.in;217154349;4 and hash 27
36(27187) DEBUG: cdp [session.c:315]: cdp_get_session(): no session found
22(27169) DEBUG: cdp [worker.c:343]: worker_process(): worker_process(): [3] got task Q(4/4)
22(27169) DEBUG: tm [t_lookup.c:1563]: t_lookup_ident(): transaction found
22(27169) DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
22(27169) DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg(): method: <REGISTER>
22(27169) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): uri: <sip:scscf.tera-ims.in>
22(27169) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): version: <SIP/2.0>
22(27169) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK14cd.c01e4771e6f86dc08a04af6bac0dcd71.0>; state=16
22(27169) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
22(27169) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
22(27169) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
22(27169) INFO: ims_auth [cxdx_avp.c:137]: cxdx_get_avp(): cxdx_get_experimental_result_code: Failed finding avp (avp_code = 297, vendor_id = 0)
22(27169) DEBUG: ims_auth [authorize.c:1565]: pack_challenge(): setting QOP str used is [, qop="auth,auth-int"]
22(27169) DEBUG: ims_auth [authorize.c:1567]: pack_challenge(): QOP str used is [, qop="auth,auth-int"]
22(27169) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK14cd.7b42807438c37ed99c99b288ebf43a5a.0>; state=16
22(27169) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
22(27169) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=ffffffffffffffff
22(27169) DEBUG: <core> [core/parser/msg_parser.c:504]: parse_headers(): this is the second via
22(27169) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
22(27169) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK4a625e7e86ab68ed>; state=16
22(27169) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
22(27169) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=ffffffffffffffff
22(27169) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
22(27169) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [24]; uri=[sip:5252 at tera-ims.in]
22(27169) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:5252 at tera-ims.in>
]
22(27169) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <48701> <REGISTER>
22(27169) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0
22(27169) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
22(27169) DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (192.168.12.14, 192.168.12.14, 1)
22(27169) DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers reset
22(27169) DEBUG: tm [t_reply.c:598]: _reply_light(): reply sent out. buf=0x7f57b1ce4478: SIP/2.0 401 Unauthor..., shmem=0x7f57a7a678b8: SIP/2.0 401 Unauthor
22(27169) DEBUG: tm [t_reply.c:608]: _reply_light(): finished
22(27169) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:5252 at tera-ims.in (Hash 571)
22(27169) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
22(27169) DEBUG: ims_auth [authorize.c:1689]: add_auth_vector(): Adding auth_vector (status 1) for IMPU sip:5252 at tera-ims.in / IMPI 5252 at tera-ims.in (Hash 571)
22(27169) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f57a7a65bb8) 303
22(27169) DEBUG: ims_auth [cxdx_mar.c:464]: async_cdp_callback(): DBG:UAR Async CDP callback: ... Done resuming transaction
22(27169) INFO: ims_auth [cxdx_mar.c:79]: create_return_code(): created AVP successfully : [maa_return_code] - [1]
22(27169) DEBUG: tm [t_lookup.c:1563]: t_lookup_ident(): transaction found
22(27169) DEBUG: <script>: maa_return code is 1
22(27169) DEBUG: <script>: MAR success - 401/407 response sent from module
22(27169) DEBUG: ims_auth [cxdx_mar.c:87]: free_saved_transaction_data(): Freeing saved transaction data: async
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
11(27145) DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
11(27145) DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg(): method: <REGISTER>
11(27145) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): uri: <sip:scscf.tera-ims.in>
11(27145) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): version: <SIP/2.0>
11(27145) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKe3cd.81780282d40076286f9669bfb4d60747.0>; state=16
11(27145) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
11(27145) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
11(27145) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
11(27145) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKe3cd.cd52c4a99a3f6c081bea7a5eae12f943.0>; state=16
11(27145) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
11(27145) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=78
11(27145) DEBUG: <core> [core/parser/msg_parser.c:504]: parse_headers(): this is the second via
11(27145) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
11(27145) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK3d72e1217cab892f>; state=16
11(27145) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
11(27145) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=78
11(27145) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
11(27145) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [26]; uri=[sip:5252 at 192.168.12.14]
11(27145) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:5252 at 192.168.12.14>
]
11(27145) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <48702> <REGISTER>
11(27145) DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - request - call-id: [2722461655-4273533943 at 192.168.12.31] - cseq: [48702 REGISTER]
11(27145) DEBUG: <core> [core/receive.c:234]: receive_msg(): preparing to run routing scripts...
11(27145) ERROR: <script>: Inside route{........}
11(27145) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=a53af0c597778a10-a34ef033
11(27145) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
11(27145) ERROR: <script>: REGISTER (sip:5252 at 192.168.12.14 (192.168.12.14:4060) to sip:5252 at 192.168.12.14, 2722461655-4273533943 at 192.168.12.31)
11(27145) DEBUG: <script>: Mem: Total 67108864, Free 63389224 [1% used]
11(27145) DEBUG: maxfwd [mf_funcs.c:76]: is_maxfwd_present(): value = 68
11(27145) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0
11(27145) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
11(27145) DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1
11(27145) DEBUG: siputils [checks.c:120]: has_totag(): no totag
11(27145) DEBUG: <core> [core/select.c:412]: run_select(): Calling SELECT 0x7f57b1c1a310
11(27145) DEBUG: tm [t_lookup.c:1001]: t_check_msg(): msg (0x7f57b1ce2dc0) id=1 global id=0 T start=0xffffffffffffffff
11(27145) DEBUG: tm [t_lookup.c:459]: t_lookup_request(): start searching: hash=56382, isACK=0
11(27145) DEBUG: tm [t_lookup.c:417]: matching_3261(): RFC3261 transaction matching failed
11(27145) DEBUG: tm [t_lookup.c:641]: t_lookup_request(): no transaction found
11(27145) DEBUG: tm [t_lookup.c:1070]: t_check_msg(): msg (0x7f57b1ce2dc0) id=1 global id=1 T end=(nil)
11(27145) DEBUG: pv [pv_core.c:1262]: pv_get_authattr(): no [Proxy-]Authorization header
11(27145) ERROR: <script>: ALGORITHM IS [<null>] and User-Agent is [F612/V6.0.10P1T5]
11(27145) DEBUG: pv [pv_core.c:1262]: pv_get_authattr(): no [Proxy-]Authorization header
11(27145) DEBUG: pv [pv_core.c:1262]: pv_get_authattr(): no [Proxy-]Authorization header
11(27145) DEBUG: ims_auth [authorize.c:734]: authenticate(): Running authenticate, is_proxy_auth=0
11(27145) DEBUG: ims_auth [authorize.c:754]: authenticate(): Checking if REGISTER is authorized for realm [192.168.12.14]...
11(27145) DEBUG: ims_auth [authorize.c:792]: authenticate(): Nonce or response missing: nonce len [1870209134], response16 len[1869180009]
11(27145) DEBUG: <script>: About to challenge! auth_ims
11(27145) DEBUG: ims_auth [authorize.c:299]: challenge(): Looking for route block [REG_MAR_REPLY]
11(27145) INFO: ims_auth [cxdx_mar.c:79]: create_return_code(): created AVP successfully : [maa_return_code] - [-2]
11(27145) DEBUG: ims_auth [authorize.c:323]: challenge(): Need to challenge for realm [192.168.12.14]
11(27145) DEBUG: ims_auth [authorize.c:330]: challenge(): Checking if REGISTER is authorized for realm [192.168.12.14]...
11(27145) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:5252 at 192.168.12.14 (Hash 701)
11(27145) DEBUG: tm [t_lookup.c:1302]: t_newtran(): msg id=1 , global msg id=1 , T on entrance=(nil)
11(27145) DEBUG: tm [t_lookup.c:459]: t_lookup_request(): start searching: hash=56382, isACK=0
11(27145) DEBUG: tm [t_lookup.c:417]: matching_3261(): RFC3261 transaction matching failed
11(27145) DEBUG: tm [t_lookup.c:641]: t_lookup_request(): no transaction found
11(27145) DEBUG: tm [t_hooks.c:349]: run_reqin_callbacks_internal(): trans=0x7f57a7a5a518, callback type 1, id 0 entered
11(27145) DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 calculated: 363097030117fb50c0a82bb135114ff7
11(27145) DEBUG: ims_auth [authorize.c:466]: challenge(): Suspending SIP TM transaction
11(27145) DEBUG: ims_auth [authorize.c:1534]: multimedia_auth_request(): Sending MAR
11(27145) DEBUG: cdp [session.c:285]: cdp_add_session(): adding a session with id scscf.tera-ims.in;217154349;5
11(27145) DEBUG: cdp [session.c:306]: cdp_get_session(): called get session with id scscf.tera-ims.in;217154349;5 and hash 28
11(27145) DEBUG: cdp [session.c:315]: cdp_get_session(): no session found
11(27145) DEBUG: cdp [routing.c:202]: get_routing_peer(): getting diameter routing peer for realm: [tera-ims.in]
11(27145) DEBUG: cdp [routing.c:271]: get_routing_peer(): no routing peer found, trying default route
11(27145) DEBUG: cdp [routing.c:129]: get_first_connected_route(): The peer hss.tera-ims.in state is opened
11(27145) DEBUG: cdp [routing.c:83]: peer_handles_application(): Checking if peer hss.tera-ims.in handles application 16777216 for vendord 10415
11(27145) DEBUG: cdp [routing.c:131]: get_first_connected_route(): The peer hss.tera-ims.in matches - will forward there
11(27145) DEBUG: cdp [routing.c:149]: get_first_connected_route(): peer [hss.tera-ims.in] was last used @ 1539146697716282
11(27145) DEBUG: cdp [routing.c:162]: get_first_connected_route(): chosen peer [hss.tera-ims.in]
11(27145) DEBUG: cdp [diameter_comm.c:145]: AAASendMessage(): Found diameter peer [hss.tera-ims.in] from routing table
11(27145) DEBUG: cdp [peerstatemachine.c:90]: sm_process(): sm_process(): Peer hss.tera-ims.in State I_Open Event Send_Message
11(27145) DEBUG: cdp [peerstatemachine.c:1142]: Snd_Message(): Snd_Message called to peer [hss.tera-ims.in] for request with code 303
11(27145) DEBUG: cdp [session.c:306]: cdp_get_session(): called get session with id scscf.tera-ims.in;217154349;5 and hash 28
11(27145) DEBUG: cdp [session.c:315]: cdp_get_session(): no session found
11(27145) DEBUG: cdp [diameter_msg.c:81]: AAABuildMsgBuffer(): AAABuildMsgBuffer(): len=324
11(27145) DEBUG: cdp [receiver.c:994]: peer_send_msg(): peer_send_msg(): Pipe push [0x7f57a7a65bb8]
11(27145) DEBUG: ims_auth [cxdx_mar.c:549]: cxdx_send_mar(): Successfully sent async diameter
11(27145) DEBUG: <core> [core/receive.c:275]: receive_msg(): request-route executed in: 1519 usec
11(27145) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
36(27187) DEBUG: cdp [receiver.c:751]: receive_loop(): select_recv(): There is something on the send pipe
11(27145) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
11(27145) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
11(27145) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
11(27145) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
11(27145) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
11(27145) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
36(27187) DEBUG: cdp [receiver.c:764]: receive_loop(): select_recv(): Send pipe says [0x7f57a7a65bb8] 8
11(27145) DEBUG: <core> [core/receive.c:364]: receive_msg(): cleaning up
36(27187) DEBUG: cdp [diameter_msg.c:410]: AAAFreeMessage(): AAAFreeMessage: Freeing message (0x7f57a7a65bb8) 303
36(27187) DEBUG: cdp [receiver.c:574]: do_receive(): receive_loop(): [hss.tera-ims.in] Recv Version 1 Length 180
36(27187) DEBUG: cdp [receiver.c:1088]: receive_message(): receive_message(): [hss.tera-ims.in] Recv msg 303
36(27187) DEBUG: cdp [peerstatemachine.c:90]: sm_process(): sm_process(): Peer hss.tera-ims.in State I_Open Event I_Rcv_Message
36(27187) DEBUG: cdp [session.c:306]: cdp_get_session(): called get session with id scscf.tera-ims.in;217154349;5 and hash 28
36(27187) DEBUG: cdp [session.c:315]: cdp_get_session(): no session found
23(27170) DEBUG: cdp [worker.c:343]: worker_process(): worker_process(): [4] got task Q(5/5)
23(27170) DEBUG: tm [t_lookup.c:1563]: t_lookup_ident(): transaction found
23(27170) DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
23(27170) DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg(): method: <REGISTER>
23(27170) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): uri: <sip:scscf.tera-ims.in>
23(27170) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): version: <SIP/2.0>
23(27170) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKe3cd.81780282d40076286f9669bfb4d60747.0>; state=16
23(27170) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
23(27170) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
23(27170) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
23(27170) INFO: ims_auth [cxdx_avp.c:137]: cxdx_get_avp(): cxdx_get_user_name: Failed finding avp (avp_code = 1, vendor_id = 0)
23(27170) ERROR: ims_auth [cxdx_mar.c:151]: async_cdp_callback(): No private identity specified (Authorization: username)
23(27170) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKe3cd.cd52c4a99a3f6c081bea7a5eae12f943.0>; state=16
23(27170) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
23(27170) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=ffffffffffffffff
23(27170) DEBUG: <core> [core/parser/msg_parser.c:504]: parse_headers(): this is the second via
23(27170) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
23(27170) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK3d72e1217cab892f>; state=16
23(27170) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
23(27170) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=ffffffffffffffff
23(27170) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
23(27170) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [26]; uri=[sip:5252 at 192.168.12.14]
23(27170) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:5252 at 192.168.12.14>
]
23(27170) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <48702> <REGISTER>
23(27170) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0
23(27170) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
23(27170) DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (192.168.12.14, 192.168.12.14, 1)
23(27170) DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers reset
23(27170) DEBUG: tm [t_reply.c:598]: _reply_light(): reply sent out. buf=0x7f57b1ce4258: SIP/2.0 403 Forbidde..., shmem=0x7f57a7a67ee8: SIP/2.0 403 Forbidde
23(27170) DEBUG: tm [t_reply.c:608]: _reply_light(): finished
23(27170) DEBUG: tm [t_lookup.c:1563]: t_lookup_ident(): transaction found
23(27170) DEBUG: <script>: maa_return code is -2
23(27170) ERROR: <script>: MAR error - sending error response now
23(27170) DEBUG: tm [t_lookup.c:1001]: t_check_msg(): msg (0x7f57a7a68a00) id=0 global id=0 T start=0x7f57a7a5a518
23(27170) DEBUG: tm [t_lookup.c:1073]: t_check_msg(): T (0x7f57a7a5a518) already found for msg (0x7f57a7a68a00)!
23(27170) DEBUG: tm [tm.c:1243]: w_t_reply(): t_reply_unsafe called from w_t_reply
23(27170) DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (192.168.12.14, 192.168.12.14, 1)
23(27170) ERROR: tm [t_reply.c:482]: _reply_light(): can't generate 500 reply when a final 403 was sent out
23(27170) DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers reset
23(27170) DEBUG: <core> [core/timer.c:575]: timer_add_safe(): timer_add called on an active timer 0x7f57a7a5a598 (0x7f57a7750378, 0x7f57a7750378), flags 201
23(27170) DEBUG: tm [t_funcs.c:148]: put_on_wait(): tm: put_on_wait: transaction 0x7f57a7a5a518 already on wait
23(27170) ERROR: sl [sl.c:271]: send_reply(): failed to reply stateful (tm)
23(27170) DEBUG: ims_auth [cxdx_mar.c:87]: free_saved_transaction_data(): Freeing saved transaction data: async
13(27147) DEBUG: presence [subscribe.c:2499]: timer_db_update(): db_update timer
13(27147) DEBUG: presence [subscribe.c:2222]: update_db_subs_timer(): update_db_subs_timer: start
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(27147) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(27147) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(27147) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 69028847
13(27147) DEBUG: ims_auth [authorize.c:199]: reg_await_timer(): Slot 571 <5252 at tera-ims.in>
13(27147) DEBUG: ims_auth [authorize.c:204]: reg_await_timer(): .. AV 1 - 1 Exp 69028902 0x7f57a7a65d38
13(27147) DEBUG: ims_auth [authorize.c:204]: reg_await_timer(): .. AV 1 - 2 Exp 69028902 0x7f57a7a62988
13(27147) DEBUG: ims_auth [authorize.c:210]: reg_await_timer(): ... dropping av 1 - 2
13(27147) DEBUG: ims_auth [authorize.c:204]: reg_await_timer(): .. AV 1 - 2 Exp 69029115 0x7f57a7a5d8a8
13(27147) DEBUG: ims_auth [authorize.c:210]: reg_await_timer(): ... dropping av 1 - 2
13(27147) DEBUG: ims_auth [authorize.c:199]: reg_await_timer(): Slot 701 <5252 at 192.168.12.14>
13(27147) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 69028847
14(27148) DEBUG: tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7f57a7a65e10 from timer.c:651
14(27148) DEBUG: tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7f57a7a5f3e0 from timer.c:651
38(27189) DEBUG: cdp [peermanager.c:263]: peer_timer(): peer_timer(): taking care of peers...
14(27148) DEBUG: tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7f57a7a5a518 from timer.c:651
13(27147) DEBUG: dispatcher [dispatch.c:2700]: ds_check_timer(): no destination sets
0(27131) DEBUG: <core> [main.c:695]: handle_sigs(): SIGTERM received, program terminates
0(27131) NOTICE: <core> [main.c:696]: handle_sigs(): Thank you for flying kamailio!!!
41(27210) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
38(27189) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
37(27188) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
36(27187) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
34(27185) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
33(27184) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
28(27175) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
27(27174) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
23(27170) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
17(27163) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
13(27147) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
10(27144) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
5(27138) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
40(27209) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
3(27135) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
35(27186) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
31(27182) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
25(27172) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
30(27179) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
20(27166) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
29(27178) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
24(27171) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
1(27133) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
21(27168) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
16(27158) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
6(27139) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
18(27164) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
15(27149) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
9(27143) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
14(27148) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
12(27146) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
8(27142) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
2(27134) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
7(27141) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
4(27136) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
42(27211) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
11(27145) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
19(27165) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
39(27208) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
22(27169) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
32(27183) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
26(27173) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
0(27131) DEBUG: debugger [debugger_api.c:1267]: dbg_destroy_mod_levels(): Destroyed _dbg_mod_table, size 32
0(27131) DEBUG: ims_usrloc_scscf [udomain.c:277]: mem_timer_udomain(): Changing expired_contacts list size from 0 to 1024
0(27131) DEBUG: ims_usrloc_scscf [udomain.c:291]: mem_timer_udomain(): *** mem_timer_udomain - checking contacts - START ***
0(27131) DEBUG: ims_usrloc_scscf [udomain.c:304]: mem_timer_udomain(): We have a [3gpp=0] contact in the new contact list in slot 196 = [sip:5252 at tera-ims.in] (sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1) which expires in 22.000000 seconds and has a ref count of 1 (state: Contact valid)
0(27131) DEBUG: ims_usrloc_scscf [udomain.c:353]: mem_timer_udomain(): *** mem_timer_udomain - checking contacts - FINISHED ***
0(27131) DEBUG: ims_usrloc_scscf [udomain.c:359]: mem_timer_udomain(): *** mem_timer_udomain - checking IMPUs - START ***
0(27131) DEBUG: ims_usrloc_scscf [impurecord.c:372]: process_impurecord(): Checking validity of IMPU: <sip:5252 at tera-ims.in> registration subscriptions
0(27131) DEBUG: ims_usrloc_scscf [impurecord.c:386]: process_impurecord(): DBG:registrar_timer: Subscriber with watcher_contact <sip:pcscf.tera-ims.in> and presentity uri <sip:5252 at tera-ims.in> is valid and expires in 3662 seconds.
0(27131) DEBUG: ims_usrloc_scscf [impurecord.c:388]: process_impurecord(): Hash size: <512> 0(27131) DEBUG: ims_usrloc_scscf [impurecord.c:389]: process_impurecord(): Searching sub dialog hash info with call_id: <728c7ec248d1f6d2-27025 at 192.168.12.14> and ttag <53f4d4fdca30a8a1b8f60ced3dd1ac56-fc25> ftag <b73efefe53cbd90b898919c483e5f28e-1f24> and hash code <1> 0(27131) ERROR: ims_usrloc_scscf [impurecord.c:394]: process_impurecord(): DBG:registrar_timer: Subscription has no dialog record in hash table
0(27131) DEBUG: ims_usrloc_scscf [impurecord.c:409]: process_impurecord(): Public Identity sip:5252 at tera-ims.in, Barred: [0], State: [registered], contacts [1], 3gppcontacts [0]
0(27131) DEBUG: ims_usrloc_scscf [impurecord.c:442]: process_impurecord(): Contact #0 - sip:5252 at 192.168.12.31:5060;alias=192.168.12.31~5060~1, Ref [1] (expires in 22 seconds) (State: 0)
0(27131) DEBUG: ims_usrloc_scscf [udomain.c:384]: mem_timer_udomain(): *** mem_timer_udomain - checking IMPUs - FINISHED ***
0(27131) DEBUG: <core> [db_pool.c:100]: pool_remove(): removing connection from the pool
0(27131) DEBUG: ims_usrloc_scscf [impurecord.c:176]: free_impurecord(): free_impurecord
0(27131) DEBUG: ims_usrloc_scscf [impurecord.c:1284]: unref_subscription_unsafe(): un-reffing subscription [5252 at tera-ims.in] - was [1]
0(27131) DEBUG: ims_usrloc_scscf [udomain.c:824]: delete_subscription(): Deleting subscription 0x7f57a7a5d498 [5252 at tera-ims.in]
0(27131) DEBUG: ims_usrloc_scscf [subscribe.c:415]: free_subscriber(): Freeing subscriber memory 0(27131) DEBUG: ims_usrloc_scscf [subscribe.c:427]: free_subscriber(): Removing sub dialog hash info with call_id: <728c7ec248d1f6d2-27025 at 192.168.12.14> and ttag <53f4d4fdca30a8a1b8f60ced3dd1ac56-fc25> and ftag <b73efefe53cbd90b898919c483e5f28e-1f24> and hash code <1> 0(27131) ERROR: ims_usrloc_scscf [subscribe.c:430]: free_subscriber(): record not found in hash table
0(27131) DEBUG: cdp_avp [cdp_avp_mod.c:224]: cdp_avp_destroy(): Destroying module cdp_avp
0(27131) INFO: cdp [cdp_mod.c:257]: cdp_exit(): CDiameterPeer child stopping ...
0(27131) INFO: cdp [diameter_peer.c:364]: diameter_peer_destroy(): destroy_diameter_peer(): Terminating all children...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27189] to terminate...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27188] to terminate...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27187] to terminate...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27186] to terminate...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27185] to terminate...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27184] to terminate...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27183] to terminate...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27182] to terminate...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27179] to terminate...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27178] to terminate...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27175] to terminate...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27174] to terminate...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27173] to terminate...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27172] to terminate...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27171] to terminate...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27170] to terminate...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27169] to terminate...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27168] to terminate...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27166] to terminate...
0(27131) INFO: cdp [diameter_peer.c:371]: diameter_peer_destroy(): destroy_diameter_peer(): Waiting for child [27165] to terminate...
0(27131) INFO: cdp [diameter_peer.c:383]: diameter_peer_destroy(): destroy_diameter_peer(): All processes terminated. Cleaning up.
0(27131) INFO: cdp [worker.c:139]: worker_destroy(): Unlocking workers waiting on empty queue...
0(27131) INFO: cdp [worker.c:142]: worker_destroy(): Unlocking workers waiting on full queue...
0(27131) DEBUG: cdp [peermanager.c:129]: peer_manager_destroy(): peer_manager_init(): ...Peer Manager destroyed
0(27131) CRITICAL: cdp [diameter_peer.c:423]: diameter_peer_destroy(): destroy_diameter_peer(): Bye Bye from C Diameter Peer test
0(27131) INFO: cdp [cdp_mod.c:259]: cdp_exit(): ... CDiameterPeer child stopped
0(27131) DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f57b1cb3b60 not found in pool
0(27131) DEBUG: db_mysql [km_my_con.c:98]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@192.168.12.14/scscf
0(27131) DEBUG: db_mysql [km_my_con.c:136]: db_mysql_new_connection(): connection type is 192.168.12.14 via TCP/IP
0(27131) DEBUG: db_mysql [km_my_con.c:137]: db_mysql_new_connection(): protocol version is 10
0(27131) DEBUG: db_mysql [km_my_con.c:138]: db_mysql_new_connection(): server version is 5.5.59-0+deb8u1
0(27131) DEBUG: presence [subscribe.c:2499]: timer_db_update(): db_update timer
0(27131) DEBUG: presence [subscribe.c:2222]: update_db_subs_timer(): update_db_subs_timer: start
0(27131) DEBUG: <core> [db_pool.c:100]: pool_remove(): removing connection from the pool
0(27131) DEBUG: tm [t_funcs.c:86]: tm_shutdown(): DEBUG: tm_shutdown : start
0(27131) DEBUG: tm [t_funcs.c:89]: tm_shutdown(): DEBUG: tm_shutdown : emptying hash table
0(27131) DEBUG: tm [t_funcs.c:91]: tm_shutdown(): DEBUG: tm_shutdown : removing semaphores
0(27131) DEBUG: tm [t_funcs.c:93]: tm_shutdown(): DEBUG: tm_shutdown : destroying tmcb lists
0(27131) DEBUG: tm [t_funcs.c:96]: tm_shutdown(): DEBUG: tm_shutdown : done
0(27131) INFO: <core> [core/sctp_core.c:53]: sctp_core_destroy(): SCTP API not initialized
0(27131) DEBUG: <core> [core/mem/shm.c:174]: shm_core_lock_destroy(): destroying the shared memory lock
0(27131) DEBUG: <core> [core/mem/shm.c:266]: shm_destroy_manager(): destroying memory manager: q_malloc
0(27131) DEBUG: <core> [core/mem/pkg.c:89]: pkg_destroy_manager(): destroying memory manager: q_malloc
More information about the sr-users
mailing list