Sems-yeti config ERROR: missed 'cdr_completed_dir'' parameter

rabbani · April 5, 2022, 12:08pm

Hi,

Here is the error I’m seeing with sems-yeti 1.9

I was testing failover to file config and sems could not start due to some missing parameter in cdr_completed_dir

~/yeti/system.cfg
…

failover_requeue = true
failover_to_file = true
serialize_dynamic_fields = true
batch_size = 1
batch_timeout = 5000

…

systemctl restart yeti-management restart
systemctl restart sems
results in Error. Refer to log below:

~/sems/sems.log

sems[11935]: [11935/11935] [yeti:SqlRouter.cpp:230] INFO: SqlRouter::db_configure: config successfuly readed
sems[11935]: [11935/11935] [yeti:cdr/CdrWriter.cpp:873] ERROR: missed 'cdr_completed_dir'' parameter
sems[11935]: [11935/11935] [yeti:SqlRouter.cpp:244] INFO: Cdr writer pool config loading error
sems[11935]: [11935/11935] [yeti:yeti.cpp:354] ERROR: SqlRouter configure failed
sems[11935]: [11935/11935] [yeti:SBC.cpp:119] ERROR: yeti configuration error

dmitry.s · April 5, 2022, 12:26pm

have you tried to add this parameter?

rabbani · April 5, 2022, 10:14pm

Yes, here is the cdr section in system.cfg

For some reason, it is not recognising the parameter set in competed_dir = even with quotes completed_dir = '/var/spool/sems/cdrs/completed' or completed_dir = "/var/spool/sems/cdrs/completed". I also tried to add cdr_completed_dir = /var/spool/sems/cdrs/completed with resulted in error

Any direction why is this happening?

 cdr {
       dir = /var/spool/sems/cdrs
       completed_dir = /var/spool/sems/cdrs/completed
       pool_size = 2
       schema = switch
       function = writecdr
       master {
         host = 1.1.1.1.
         port = 5432
         name = cdrdb
         user = cdruser
         pass = somepass
      }
       failover_to_slave = false
       slave {
         host = 2.2.2.2
         port = 5432
         name = cdrdb
         user = cdrser
         pass = somepassword
       }
       failover_requeue = true
       failover_to_file = true
       serialize_dynamic_fields = true
       batch_size = 1
       batch_timeout = 5000
     }

rabbani · April 10, 2022, 10:59pm

Hi @dmitry.s , Is there a particular way to add this parameter? I followed the documentation method mentioned above.

dmitry.s · April 12, 2022, 9:15pm

what error? look like parameter name is cdr_completed_dir. Anyway this feature is not tested properly, and will be removed in future versions.

rabbani · April 13, 2022, 12:25am

[apps/jsonrpc/RpcServerLoop.cpp:437] INFO: running event loop
[apps/sctp_bus/SctpClientConnection.cpp:99] ERROR: yeti-management-ip:4444 (67,9) connection error: Connection refused

The above is the error I get when I use cdr_completed_dir as the parameter in the config below :

  cdr {
   dir = /var/spool/sems/cdrs
   cdr_completed_dir = /var/spool/sems/cdrs/completed
   pool_size = 2
   schema = switch
   function = writecdr
   master {
     host = 1.1.1.1
     port = 5432
     name = cdrdb
     user = cdrdb
     pass = somepass
  }
   failover_to_slave = false
   slave {
     host = 2.2.2.2
     port = 5432
     name = cdrdb
     user = cdrmaster
     pass = somepass
   }
   failover_requeue = true
   failover_to_file = true
   serialize_dynamic_fields = true
   batch_size = 1
   batch_timeout = 5000
 }

@dmitry.s If the failover to file feature is not fully tested or to be removed in the future version, what is the recommended failover option now?

Do we failover to a secondary or standalone CDR master database, if so, how would we sync it back to the primary cdr master DB without having any records conflict?

Appreciate your advice!!

dmitry.s · April 13, 2022, 8:11am

your yeti-management daemon is not available. you have to check it first.

rabbani · April 14, 2022, 2:44am

Yes, Yeti-management fails to start when I set cdr_completed_dir = /var/spool/sems/cdrs/completed instead of completed_dir = /var/spool/sems/cdrs/completed in yeti/system.cfg

I believe the concept and purpose of failover_to_file were misunderstood, instead, we think it is the failover_requeue that will be useful to test in our case.

The test case objective was to test SEMS failing over to local memory to store CDR in case of a full database outage and continue to function independently.

Our database setup is below:

postgres=# \l
                                  List of databases
   Name    |   Owner   | Encoding |   Collate   |    Ctype    |   Access privileges
-----------+-----------+----------+-------------+-------------+-----------------------
 cdrdb     | cdrmaster | UTF8     | en_US.UTF-8 | en_US.UTF-8 |
 postgres  | postgres  | UTF8     | en_US.UTF-8 | en_US.UTF-8 |

We turn off the database: systemctl stop postgresql@11-main.service

The error we are seeing:

Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:cdr/Cdr.cpp:178] DEBUG: Cdr::update_sql(SqlCallProfile)
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:SBC.cpp:254] DEBUG: PROFILING: get profiles took 0.000394
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:CodesTranslator.cpp:346] DEBUG: translate_db_code: 121, override_id: 0
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:CodesTranslator.cpp:334] DEBUG: translation result: internal = <500:'failed to get active connection'>, response = <500:'Internal Server Error'>, silently_drop = 0, store_cdr = 1
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:cdr/Cdr.cpp:426] DEBUG: Cdr[0x7feca800beb0]::update_internal_reason(initiator = 0,reason = 'failed to get active connection',code = 500) cdr.disconnect_initiator_writed = 0

Full error log: tail -f /var/log/sems/sems.log

Apr 13 23:44:57 rtp-sems sems[22484]: [22524/yeti:cdr/CdrWriter.cpp:652] ERROR: CdrWriter: SQL connection exception: could not connect to server: Connection refused#012#011Is the server running on host "127.0.0.1" and accepting#012#011TCP/IP connections on port 5432?
Apr 13 23:44:57 rtp-sems sems[22480]:  [22484/22526] [yeti:cdr/CdrWriter.cpp:652] ERROR: CdrWriter: SQL connection exception: could not connect to server: Connection refused
Apr 13 23:44:57 rtp-sems sems[22480]: #011Is the server running on host "127.0.0.1" and accepting
Apr 13 23:44:57 rtp-sems sems[22480]: #011TCP/IP connections on port 5432?
Apr 13 23:44:57 rtp-sems sems[22484]: [22526/yeti:cdr/CdrWriter.cpp:652] ERROR: CdrWriter: SQL connection exception: could not connect to server: Connection refused#012#011Is the server running on host "127.0.0.1" and accepting#012#011TCP/IP connections on port 5432?

Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/udp_trsp.cpp:363] DEBUG: vv M [|] u recvd msg via UDP from kam_lb:port vv#012--++--#012INVITE sip:0411111111@lb.domain:port;transport=UDP SIP/2.0#015#012Record-Route: <sip:lb.ip:port;lr;ftag=fa764333>#015#012Via: SIP/2.0/UDP public_ip:7000;branch=z9hG4bK326f.8a76c4e04b7909a59c8c271ef677fc96.0#015#012Via: SIP/2.0/UDP uac_public_ip:5060;received=uac_public_ip;branch=z9hG4bK-d8754z-6a1a2a2862cf78bc-1---d8754z-;rport=5060#015#012Max-Forwards: 69#015#012Contact: <sip:61388140397@uac_public_ip:5060;transport=UDP>#015#012To: <sip:0411111111@lb.domain:7000;transport=UDP>#015#012From: "61388140397"<sip:61388140397@lb.domain:7000;transport=UDP>;tag=fa764333#015#012Call-ID: YmRmYzQ5NWU5MjY5NzYyMmIzMWUzY2JlMTM5MzdiMmY.#015#012CSeq: 1 INVITE#015#012Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE#015#012Content-Type: application/sdp#015#012Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri#015#012User-Agent: Z 3.6.25251 r25476#015#012Allow-Events: presence, kpml#015#012Content-Length: 242#015#012X-ORIG-IP: uac_public_ip#015#012X-ORIG-PORT: 5060#015#012X-ORIG-PROTO: 1#015#012#015#012v=0#015#012o=Z 0 0 IN IP4 192.168.1.234#015#012s=Z#015#012c=IN IP4 192.168.1.234#015#012t=0 0#015#012m=audio 16834 RTP/AVP 3 110 8 0 98 101#015#012a=rtpmap:110 speex/8000#015#012a=rtpmap:98 iLBC/8000#015#012a=fmtp:98 mode=20#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=sendrecv#015#012--++--
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/parse_uri.cpp:352] DEBUG: Converted URI port (7000) to int (7000)
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/parse_via.cpp:548] DEBUG: parsed branch: z9hG4bK326f.8a76c4e04b7909a59c8c271ef677fc96.0
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/parse_via.cpp:571] DEBUG: has_rport: 0
Apr 13 23:45:00 rtp-sems sems[22480]:  [22484/22536] [yeti:SqlRouter.cpp:383] ERROR: SQL cant get profiles. Drop request
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/trans_table.cpp:99] DEBUG: Matching INVITE request
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/parse_uri.cpp:352] DEBUG: Converted URI port (5060) to int (5060)
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/AmMimeBody.cpp:597] DEBUG: saving single-part body
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/SipCtrlInterface.cpp:1040] DEBUG: MIME body successfully parsed
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/SipCtrlInterface.cpp:1218] DEBUG: Received new request from <public_ip:7000/udp> on intf #0
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/SipCtrlInterface.cpp:1222] DEBUG: req.method = <INVITE>
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/SipCtrlInterface.cpp:1225] DEBUG: req.r_uri = <sip:0411111111@lb.domain:7000;transport=UDP>
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/SipCtrlInterface.cpp:1226] DEBUG: req.from_uri = <sip:11111111111@uac_public_ip:5060;transport=UDP>
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/SipCtrlInterface.cpp:1227] DEBUG: req.from = <"11111111111" <sip:11111111111@lb.domain:7000;transport=UDP>>
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/SipCtrlInterface.cpp:1228] DEBUG: req.to = <<sip:0411111111@lb.domain:7000;transport=UDP>>
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/SipCtrlInterface.cpp:1229] DEBUG: req.callid = <YmRmYzQ5NWU5MjY5NzYyMmIzMWUzY2JlMTM5MzdiMmY.>
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/SipCtrlInterface.cpp:1230] DEBUG: req.from_tag = <fa764333>
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/SipCtrlInterface.cpp:1231] DEBUG: req.to_tag = <>
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/SipCtrlInterface.cpp:1232] DEBUG: cseq = <1>
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/SipCtrlInterface.cpp:1233] DEBUG: req.route = <<sip:public_ip:7000;lr;ftag=fa764333>>
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/SipCtrlInterface.cpp:1234] DEBUG: hdrs = <Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE#015#012Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri#015#012User-Agent: Z 3.6.25251 r25476#015#012Allow-Events: presence, kpml#015#012X-ORIG-IP: uac_public_ip#015#012X-ORIG-PORT: 5060#015#012X-ORIG-PROTO: 1#015#012>
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/SipCtrlInterface.cpp:1235] DEBUG: body-ct = <application/sdp>
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/AmSipDispatcher.cpp:109] DEBUG: method: `INVITE' [6].
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/trans_layer.cpp:449] DEBUG: reply_len = 561
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/trans_layer.cpp:624] DEBUG: Sending to public_ip:7000 <SIP/2.0 100 Connecting#015#012Record-Route: <sip:43.250....>
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/udp_trsp.cpp:289] DEBUG: send msg via UDP from public_ip:11000 to public_ip:7000#012--++--#012SIP/2.0 100 Connecting#015#012Record-Route: <sip:public_ip:7000;lr;ftag=fa764333>#015#012Via: SIP/2.0/UDP public_ip:7000;branch=z9hG4bK326f.8a76c4e04b7909a59c8c271ef677fc96.0#015#012Via: SIP/2.0/UDP uac_public_ip:5060;received=uac_public_ip;branch=z9hG4bK-d8754z-6a1a2a2862cf78bc-1---d8754z-;rport=5060#015#012To: <sip:0411111111@lb.domain:7000;transport=UDP>#015#012From: "11111111111"<sip:11111111111@lb.domain:7000;transport=UDP>;tag=fa764333#015#012Call-ID: YmRmYzQ5NWU5MjY5NzYyMmIzMWUzY2JlMTM5MzdiMmY.#015#012CSeq: 1 INVITE#015#012Server: yeti-switch 1.9.20#015#012Content-Length: 0#015#012#015#012--++--
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/trans_layer.cpp:2378] DEBUG: update_uas_reply(t=0x7feca80090b0)
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:SqlRouter.cpp:338] DEBUG: Lookup profile for request: #012 INVITE [r-uri:sip:0411111111@lb.domain:7000;transport=UDP;i:YmRmYzQ5NWU5MjY5NzYyMmIzMWUzY2JlMTM5MzdiMmY.;cseq:1;l-tag:fa764333;rtset:[<sip:public_ip:7000;lr;ftag=fa764333>];m:<sip:11111111111@uac_public_ip:5060;transport=UDP>;hdr:[Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE#015#012Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri#015#012User-Agent: Z 3.6.25251 r25476#015#012Allow-Events: presence, kpml#015#012X-ORIG-IP: uac_public_ip#015#012X-ORIG-PORT: 5060#015#012X-ORIG-PROTO: 1#015#012];user:0411111111;domain:lb.domain;f-uri:sip:11111111111@uac_public_ip:5060;transport=UDP;from:"11111111111" <sip:11111111111@lb.domain:7000;transport=UDP>;to:<sip:0411111111@lb.domain:7000;transport=UDP>;]
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:db/PgConnectionPool.cpp:182] DEBUG: : all connections inactive - returning NO connection
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:SqlRouter.cpp:358] DEBUG: Cant get active connection on
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:SqlRouter.cpp:383] ERROR: SQL cant get profiles. Drop request
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:cdr/Cdr.cpp:104] DEBUG: Cdr[0x7feca800beb0]()
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:cdr/Cdr.cpp:150] DEBUG: Cdr[0x7feca800beb0](profile = 0x7feca800b5a0)
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:cdr/Cdr.cpp:178] DEBUG: Cdr::update_sql(SqlCallProfile)
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:SBC.cpp:254] DEBUG: PROFILING: get profiles took 0.000394
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:CodesTranslator.cpp:346] DEBUG: translate_db_code: 121, override_id: 0
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:CodesTranslator.cpp:334] DEBUG: translation result: internal = <500:'failed to get active connection'>, response = <500:'Internal Server Error'>, silently_drop = 0, store_cdr = 1
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:cdr/Cdr.cpp:426] DEBUG: Cdr[0x7feca800beb0]::update_internal_reason(initiator = 0,reason = 'failed to get active connection',code = 500) cdr.disconnect_initiator_writed = 0
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:cdr/Cdr.cpp:306] DEBUG: Cdr::update_with_action(act = End)
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:cdr/Cdr.cpp:412] DEBUG: Cdr::update_aleg_reason(reason = 'Internal Server Error',code = 500)
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:cdr/Cdr.cpp:200] DEBUG: Cdr::update_with_sip_request(AmSipRequest)
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:cdr/Cdr.cpp:191] DEBUG: Cdr::update_sbc(SBCCallProfile)
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/trans_layer.cpp:449] DEBUG: reply_len = 613
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/trans_layer.cpp:624] DEBUG: Sending to public_ip:7000 <SIP/2.0 500 Internal Server Error#015#012Record-Route: <...>
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/udp_trsp.cpp:289] DEBUG: send msg via UDP from public_ip:11000 to public_ip:7000#012--++--#012SIP/2.0 500 Internal Server Error#015#012Record-Route: <sip:public_ip:7000;lr;ftag=fa764333>#015#012Via: SIP/2.0/UDP public_ip:7000;branch=z9hG4bK326f.8a76c4e04b7909a59c8c271ef677fc96.0#015#012Via: SIP/2.0/UDP uac_public_ip:5060;received=uac_public_ip;branch=z9hG4bK-d8754z-6a1a2a2862cf78bc-1---d8754z-;rport=5060#015#012To: <sip:0411111111@lb.domain:7000;transport=UDP>;tag=8-3A005615-6257607C0007704B-21FF2700#015#012From: "11111111111"<sip:11111111111@lb.domain:7000;transport=UDP>;tag=fa764333#015#012Call-ID: YmRmYzQ5NWU5MjY5NzYyMmIzMWUzY2JlMTM5MzdiMmY.#015#012CSeq: 1 INVITE#015#012Server: yeti-switch 1.9.20#015#012Content-Length: 0#015#012#015#012--++--
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/trans_layer.cpp:2378] DEBUG: update_uas_reply(t=0x7feca80090b0)
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/sip_trans.cpp:260] DEBUG: New timer of type G at time=12199 (repeated=0)(trans=0x7feca80090b0)
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/sip_trans.cpp:260] DEBUG: New timer of type H at time=13774 (repeated=0)(trans=0x7feca80090b0)
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/yeti:cdr/Cdr.cpp:164] DEBUG: ~Cdr[0x7feca800beb0]()
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/AmSessionContainer.cpp:600] DEBUG: onInvite/onRefer returned NULL
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/SipCtrlInterface.cpp:1241] DEBUG: ^^ M [YmRmYzQ5NWU5MjY5NzYyMmIzMWUzY2JlMTM5MzdiMmY.|] Ru SIP request INVITE handled ^^
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/udp_trsp.cpp:363] DEBUG: vv M [|] u recvd msg via UDP from public_ip:7000 vv#012--++--#012ACK sip:0411111111@lb.domain:7000;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP public_ip:7000;branch=z9hG4bK326f.8a76c4e04b7909a59c8c271ef677fc96.0#015#012Max-Forwards: 69#015#012To: <sip:0411111111@lb.domain:7000;transport=UDP>;tag=8-3A005615-6257607C0007704B-21FF2700#015#012From: "11111111111"<sip:11111111111@lb.domain:7000;transport=UDP>;tag=fa764333#015#012Call-ID: YmRmYzQ5NWU5MjY5NzYyMmIzMWUzY2JlMTM5MzdiMmY.#015#012CSeq: 1 ACK#015#012Content-Length: 0#015#012#015#012--++--
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/parse_uri.cpp:352] DEBUG: Converted URI port (7000) to int (7000)
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/parse_via.cpp:548] DEBUG: parsed branch: z9hG4bK326f.8a76c4e04b7909a59c8c271ef677fc96.0
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/parse_via.cpp:571] DEBUG: has_rport: 0
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/trans_table.cpp:99] DEBUG: Matching ACK request
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/trans_table.cpp:118] DEBUG: do_3261_match = 1
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/trans_layer.cpp:1794] DEBUG: ACK matched INVITE transaction 0x7feca80090b0
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/trans_layer.cpp:2455] DEBUG: update_uas_request(t=0x7feca80090b0)
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/sip_trans.cpp:202] DEBUG: Clearing old timer of type G (timer=0x7feca800ca90)(trans=0x7feca80090b0)
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/sip_trans.cpp:202] DEBUG: Clearing old timer of type H (timer=0x7feca800add0)(trans=0x7feca80090b0)
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/sip_trans.cpp:260] DEBUG: New timer of type I at time=12424 (repeated=0)(trans=0x7feca80090b0)
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/trans_layer.cpp:1797] DEBUG: update_uas_request(bucket,t=0x7feca80090b0,msg) = 6
Apr 13 23:45:00 rtp-sems sems[22484]: [22536/core/sip/trans_layer.cpp:1819] DEBUG: Absorbing non-200-ACK
Apr 13 23:45:01 rtp-sems sems[22480]:  [22484/22522] [yeti:cdr/CdrWriter.cpp:652] ERROR: CdrWriter: SQL connection exception: could not connect to server: Connection refused
Apr 13 23:45:01 rtp-sems sems[22480]: #011Is the server running on host "127.0.0.1" and accepting
Apr 13 23:45:01 rtp-sems sems[22480]: #011TCP/IP connections on port 5432?
Apr 13 23:45:01 rtp-sems sems[22484]: [22522/yeti:cdr/CdrWriter.cpp:652] ERROR: CdrWriter: SQL connection exception: could not connect to server: Connection refused#012#011Is the server running on host "127.0.0.1" and accepting#012#011TCP/IP connections on port 5432?
Apr 13 23:45:01 rtp-sems sems[22480]:  [22484/22523] [yeti:cdr/CdrWriter.cpp:652] ERROR: CdrWriter: SQL connection exception: could not connect to server: Connection refused
Apr 13 23:45:01 rtp-sems sems[22480]: #011Is the server running on host "127.0.0.1" and accepting
Apr 13 23:45:01 rtp-sems sems[22480]: #011TCP/IP connections on port 5432?
Apr 13 23:45:01 rtp-sems sems[22484]: [22523/yeti:cdr/CdrWriter.cpp:652] ERROR: CdrWriter: SQL connection exception: could not connect to server: Connection refused#012#011Is the server running on host "127.0.0.1" and accepting#012#011TCP/IP connections on port 5432?

dmitry.s · April 14, 2022, 6:26pm

according to log:

routing DB is not working
sems respond 500 because it is not possible to calculate routing without DB

rabbani · April 19, 2022, 2:16am

@dmitry.s Thank you and appreciate your assistance. To overcome this issue of access to the routing db, I have set up a separate routing DB in a different node as a slave database and the error 500 still exists but with a different error

Database setup summary and status
Master Node 1: Postgres CDR database with postgres service stopped
Slave Node 2: Postgres Routing database with portgres service running
Replication type: streaming replication

With this setup it is a different error:

Error:
Apr 19 01:48:09 rtp-sems sems[22486]: [22489/22545] [yeti:SqlRouter.cpp:498] ERROR: SQL exception for [0x7fc1580512b0]: ERROR: could not access file "$libdir/prefix": No such file or directory

Default postgress lib location is: /var/lib/postgresql/11/main

Yeti-Management setup:

 routing {
        schema = switch18
        function = route_release
        init = init
        master_pool {
          host = slave-node2-db-ip
          port = 5432
          name = routingdb
          user = rtemaster
          pass = somepass
          size = 4
          check_interval = 10
          max_exceptions = 0
          statement_timeout=3000
        }
        failover_to_slave = false
        slave_pool {
          host = master-node1-db-ip
          port = 5432
          name = routingdb
          user = rtemaster
          pass = somepass
          size = 4
          check_interval = 10
          max_exceptions = 0
          statement_timeout=3000
        }
        cache {
          enabled = false
          check_interval = 60
          buckets = 100000
        }
      }
      cdr {
       dir = /var/spool/sems/cdrs
       completed_dir = /var/spool/sems/cdrs/completed
       pool_size = 2
       schema = switch
       function = writecdr
       master {
         host = master-node1-db-ip
         port = 5432
         name = cdrdb
         user = cdrmaster
         pass = somepass
      }
       failover_to_slave = false
       slave {
         host = 127.0.0.1
         port = 5432
         name = cdrdb
         user = cdrmaster
         pass = somepass
       }
       failover_requeue = true
       failover_to_file = false
       serialize_dynamic_fields = true
       batch_size = 1
       batch_timeout = 5000
     }

Secondary Routing Database log

2022-04-19 11:47:41.307 AEST [11530] rtemaster@routingdb ERROR:  could not access file "$libdir/prefix": No such file or directory
2022-04-19 11:47:41.307 AEST [11530] rtemaster@routingdb CONTEXT:  SQL statement "SELECT                                 ca.*
                    from class4.customers_auth_normalized ca
                        JOIN public.contractors c ON c.id=ca.customer_id
                    WHERE ca.enabled AND
                      ca.ip>>=v_remote_ip AND
                      prefix_range(ca.dst_prefix)@>prefix_range(v_ret.dst_prefix_in) AND
                      prefix_range(ca.src_prefix)@>prefix_range(v_ret.src_prefix_in) AND
                      (ca.pop_id=i_pop_id or ca.pop_id is null) and
                      COALESCE(ca.x_yeti_auth,'')=v_x_yeti_auth AND
                      COALESCE(nullif(ca.uri_domain,'')=i_uri_domain,true) AND
                      COALESCE(nullif(ca.to_domain,'')=i_to_domain,true) AND
                      COALESCE(nullif(ca.from_domain,'')=i_from_domain,true) AND
                      (ca.transport_protocol_id is null or ca.transport_protocol_id=v_transport_protocol_id) AND
                      length(v_ret.dst_prefix_in) between ca.dst_number_min_length and ca.dst_number_max_length and
                      length(v_ret.src_prefix_in) between ca.src_number_min_length and ca.src_number_max_length and
                      c.enabled and c.customer
                    ORDER BY
                        masklen(ca.ip) DESC,
                        ca.transport_protocol_id is null,
                        length(prefix_range(ca.dst_prefix)) DESC,
                        length(prefix_range(ca.src_prefix)) DESC,
                        ca.pop_id is null,
                        ca.uri_domain is null,
                        ca.to_domain is null,
                        ca.from_domain is null,
                        ca.require_incoming_auth
                    LIMIT 1"
        PL/pgSQL function route_release(integer,integer,smallint,inet,integer,inet,integer,character varying,character varying,character varying,integer,character varying,character varying,integer,character varying,character varying,integer,character varying,character varying,integer,character varying,character varying,inet,integer,smallint,character varying,character varying,character varying,character varying,character varying) line 95 at SQL statement
2022-04-19 11:47:41.307 AEST [11530] rtemaster@routingdb STATEMENT:  SELECT * FROM route_release($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14,$15,$16,$17,$18,$19,$20,$21,$22,$23,$24,$25,$26,$27,$28,$29,$30);

SEMS Logs

Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/udp_trsp.cpp:363] DEBUG: vv M [|] u recvd msg via UDP from public_ip:7000 vv#012--++--#012INVITE sip:dest_num@public_domain:7000;transport=UDP SIP/2.0#015#012Record-Route: <sip:public_ip:7000;lr;ftag=79127557>#015#012Via: SIP/2.0/UDP public_ip:7000;branch=z9hG4bK279.57600643daabb3ab26430152336f0a23.0#015#012Via: SIP/2.0/UDP 207.136.8.71:5060;received=207.136.8.71;branch=z9hG4bK-d8754z-d157a7f486bb4461-1---d8754z-;rport=5060#015#012Max-Forwards: 69#015#012Contact: <sip:src_num@207.136.8.71:5060;transport=UDP>#015#012To: <sip:dest_num@public_domain:7000;transport=UDP>#015#012From: "src_num"<sip:src_num@public_domain:7000;transport=UDP>;tag=79127557#015#012Call-ID: NjNhMGU1ZDI4ZjRlMmQyYmFkMDJlYjhjYzk0MjIyN2E.#015#012CSeq: 1 INVITE#015#012Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE#015#012Content-Type: application/sdp#015#012Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri#015#012User-Agent: Z 3.6.25251 r25476#015#012Allow-Events: presence, kpml#015#012Content-Length: 242#015#012X-ORIG-IP: 207.136.8.71#015#012X-ORIG-PORT: 5060#015#012X-ORIG-PROTO: 1#015#012#015#012v=0#015#012o=Z 0 0 IN IP4 192.168.1.234#015#012s=Z#015#012c=IN IP4 192.168.1.234#015#012t=0 0#015#012m=audio 16834 RTP/AVP 3 110 8 0 98 101#015#012a=rtpmap:110 speex/8000#015#012a=rtpmap:98 iLBC/8000#015#012a=fmtp:98 mode=20#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=sendrecv#015#012--++--
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/parse_uri.cpp:352] DEBUG: Converted URI port (7000) to int (7000)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/parse_via.cpp:548] DEBUG: parsed branch: z9hG4bK279.57600643daabb3ab26430152336f0a23.0
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/parse_via.cpp:571] DEBUG: has_rport: 0
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/trans_table.cpp:99] DEBUG: Matching INVITE request
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/parse_uri.cpp:352] DEBUG: Converted URI port (5060) to int (5060)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/AmMimeBody.cpp:597] DEBUG: saving single-part body
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/SipCtrlInterface.cpp:1040] DEBUG: MIME body successfully parsed
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/SipCtrlInterface.cpp:1218] DEBUG: Received new request from <public_ip:7000/udp> on intf #0
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/SipCtrlInterface.cpp:1222] DEBUG: req.method = <INVITE>
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/SipCtrlInterface.cpp:1225] DEBUG: req.r_uri = <sip:dest_num@public_domain:7000;transport=UDP>
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/SipCtrlInterface.cpp:1226] DEBUG: req.from_uri = <sip:src_num@src_ip:5060;transport=UDP>
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/SipCtrlInterface.cpp:1227] DEBUG: req.from = <"src_num" <sip:src_num@public_domain:7000;transport=UDP>>
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/SipCtrlInterface.cpp:1228] DEBUG: req.to = <<sip:dest_num@public_domain:7000;transport=UDP>>
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/SipCtrlInterface.cpp:1229] DEBUG: req.callid = <NjNhMGU1ZDI4ZjRlMmQyYmFkMDJlYjhjYzk0MjIyN2E.>
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/SipCtrlInterface.cpp:1230] DEBUG: req.from_tag = <79127557>
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/SipCtrlInterface.cpp:1231] DEBUG: req.to_tag = <>
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/SipCtrlInterface.cpp:1232] DEBUG: cseq = <1>
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/SipCtrlInterface.cpp:1233] DEBUG: req.route = <<sip:public_ip:7000;lr;ftag=79127557>>
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/SipCtrlInterface.cpp:1234] DEBUG: hdrs = <Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE#015#012Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri#015#012User-Agent: Z 3.6.25251 r25476#015#012Allow-Events: presence, kpml#015#012X-ORIG-IP: src_ip#015#012X-ORIG-PORT: 5060#015#012X-ORIG-PROTO: 1#015#012>
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/SipCtrlInterface.cpp:1235] DEBUG: body-ct = <application/sdp>
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/AmSipDispatcher.cpp:109] DEBUG: method: `INVITE' [6].
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/trans_layer.cpp:449] DEBUG: reply_len = 561
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/trans_layer.cpp:624] DEBUG: Sending to public_ip:7000 <SIP/2.0 100 Connecting#015#012Record-Route: <sip:43.250....>
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/udp_trsp.cpp:289] DEBUG: send msg via UDP from public_ip:11000 to public_ip:7000#012--++--#012SIP/2.0 100 Connecting#015#012Record-Route: <sip:public_ip:7000;lr;ftag=79127557>#015#012Via: SIP/2.0/UDP public_ip:7000;branch=z9hG4bK279.57600643daabb3ab26430152336f0a23.0#015#012Via: SIP/2.0/UDP src_ip:5060;received=src_ip;branch=z9hG4bK-d8754z-d157a7f486bb4461-1---d8754z-;rport=5060#015#012To: <sip:dest_num@public_domain:7000;transport=UDP>#015#012From: "src_num"<sip:src_num@public_domain:7000;transport=UDP>;tag=79127557#015#012Call-ID: NjNhMGU1ZDI4ZjRlMmQyYmFkMDJlYjhjYzk0MjIyN2E.#015#012CSeq: 1 INVITE#015#012Server: yeti-switch 1.9.20#015#012Content-Length: 0#015#012#015#012--++--
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/trans_layer.cpp:2378] DEBUG: update_uas_reply(t=0x7fc130006dd0)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:338] DEBUG: Lookup profile for request: #012 INVITE [r-uri:sip:dest_num@public_domain:7000;transport=UDP;i:NjNhMGU1ZDI4ZjRlMmQyYmFkMDJlYjhjYzk0MjIyN2E.;cseq:1;l-tag:79127557;rtset:[<sip:public_ip:7000;lr;ftag=79127557>];m:<sip:src_num@src_ip:5060;transport=UDP>;hdr:[Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE#015#012Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri#015#012User-Agent: Z 3.6.25251 r25476#015#012Allow-Events: presence, kpml#015#012X-ORIG-IP: src_ip#015#012X-ORIG-PORT: 5060#015#012X-ORIG-PROTO: 1#015#012];user:dest_num;domain:public_domain;f-uri:sip:src_num@src_ip:5060;transport=UDP;from:"src_num" <sip:src_num@public_domain:7000;transport=UDP>;to:<sip:dest_num@public_domain:7000;transport=UDP>;]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:db/PgConnectionPool.cpp:212] DEBUG: : got active connection [0x7fc1580512b0]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/parse_uri.cpp:352] DEBUG: Converted URI port (7000) to int (7000)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/parse_uri.cpp:352] DEBUG: Converted URI port (5060) to int (5060)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/parse_uri.cpp:352] DEBUG: Converted URI port (7000) to int (7000)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:UsedHeaderField.cpp:89] DEBUG: no header 'X-YETI-AUTH' in SipRequest
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:UsedHeaderField.cpp:89] DEBUG: no header 'Diversion' in SipRequest
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:UsedHeaderField.cpp:158] DEBUG: X-ORIG-IP[Raw:*:] processed. got 'src_ip'
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:UsedHeaderField.cpp:158] DEBUG: X-ORIG-PORT[Raw:*:] processed. got '5060'
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:UsedHeaderField.cpp:158] DEBUG: X-ORIG-PROTO[Raw:*:] processed. got '1'
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:UsedHeaderField.cpp:89] DEBUG: no header 'P-Asserted-Identity' in SipRequest
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:UsedHeaderField.cpp:89] DEBUG: no header 'P-Preferred-Identity' in SipRequest
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:UsedHeaderField.cpp:89] DEBUG: no header 'Privacy' in SipRequest
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:UsedHeaderField.cpp:89] DEBUG: no header 'Remote-Party-ID' in SipRequest
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:UsedHeaderField.cpp:89] DEBUG: no header 'RPID-Privacy' in SipRequest
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:498] ERROR: SQL exception for [0x7fc1580512b0]: ERROR:  could not access file "$libdir/prefix": No such file or directory
Apr 19 01:48:09 rtp-sems sems[22486]: CONTEXT:  SQL statement "SELECT                                 ca.*
Apr 19 01:48:09 rtp-sems sems[22486]:             from class4.customers_auth_normalized ca
Apr 19 01:48:09 rtp-sems sems[22486]:                 JOIN public.contractors c ON c.id=ca.customer_id
Apr 19 01:48:09 rtp-sems sems[22486]:             WHERE ca.enabled AND
Apr 19 01:48:09 rtp-sems sems[22486]:               ca.ip>>=v_remote_ip AND
Apr 19 01:48:09 rtp-sems sems[22486]:               prefix_range(ca.dst_prefix)@>prefix_range(v_ret.dst_prefix_in) AND
Apr 19 01:48:09 rtp-sems sems[22486]:               prefix_range(ca.src_prefix)@>prefix_range(v_ret.src_prefix_in) AND
Apr 19 01:48:09 rtp-sems sems[22486]:               (ca.pop_id=i_pop_id or ca.pop_id is null) and
Apr 19 01:48:09 rtp-sems sems[22486]:               COALESCE(ca.x_yeti_auth,'')=v_x_yeti_auth AND
Apr 19 01:48:09 rtp-sems sems[22486]:               COALESCE(nullif(ca.uri_domain,'')=i_uri_domain,true) AND
Apr 19 01:48:09 rtp-sems sems[22486]:               COALESCE(nullif(ca.to_domain,'')=i_to_domain,true) AND
Apr 19 01:48:09 rtp-sems sems[22486]:               COALESCE(nullif(ca.from_domain,'')=i_from_domain,true) AND
Apr 19 01:48:09 rtp-sems sems[22486]:               (ca.transport_protocol_id is null or ca.transport_protocol_id=v_transport_protocol_id) AND
Apr 19 01:48:09 rtp-sems sems[22486]:               length(v_ret.dst_prefix_in) between ca.dst_number_min_length and ca.dst_number_max_length and
Apr 19 01:48:09 rtp-sems sems[22486]:               length(v_ret.src_prefix_in) between ca.src_number_min_length and ca.src_number_max_length and
Apr 19 01:48:09 rtp-sems sems[22486]:               c.enabled and c.customer
Apr 19 01:48:09 rtp-sems sems[22486]:             ORDER BY
Apr 19 01:48:09 rtp-sems sems[22486]:                 masklen(ca.ip) DESC,
Apr 19 01:48:09 rtp-sems sems[22486]:                 ca.transport_protocol_id is null,
Apr 19 01:48:09 rtp-sems sems[22486]:                 length(prefix_range(ca.dst_prefix)) DESC,
Apr 19 01:48:09 rtp-sems sems[22486]:                 length(prefix_range(ca.src_prefix)) DESC,
Apr 19 01:48:09 rtp-sems sems[22486]:                 ca.pop_id is null,
Apr 19 01:48:09 rtp-sems sems[22486]:                 ca.uri_domain is null,
Apr 19 01:48:09 rtp-sems sems[22486]:                 ca.to_domain is null,
Apr 19 01:48:09 rtp-sems sems[22486]:                 ca.from_domain is null,
Apr 19 01:48:09 rtp-sems sems[22486]:                 ca.require_incoming_auth
Apr 19 01:48:09 rtp-sems sems[22486]:             LIMIT 1"
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:498] ERROR: SQL exception for [0x7fc1580512b0]: ERROR:  could not access file "$libdir/prefix": No such file or directory#012CONTEXT:  SQL statement "SELECT                                 ca.*#012            from class4.customers_auth_normalized ca#012                JOIN public.contractors c ON c.id=ca.customer_id#012            WHERE ca.enabled AND#012              ca.ip>>=v_remote_ip AND#012              prefix_range(ca.dst_prefix)@>prefix_range(v_ret.dst_prefix_in) AND#012              prefix_range(ca.src_prefix)@>prefix_range(v_ret.src_prefix_in) AND#012              (ca.pop_id=i_pop_id or ca.pop_id is null) and#012              COALESCE(ca.x_yeti_auth,'')=v_x_yeti_auth AND#012              COALESCE(nullif(ca.uri_domain,'')=i_uri_domain,true) AND#012              COALESCE(nullif(ca.to_domain,'')=i_to_domain,true) AND#012              COALESCE(nullif(ca.from_domain,'')=i_from_domain,true) AND#012              (ca.transport_protocol_id is null or ca.transport_protocol_id=v_transport_protocol_id) AND#012              length(v_ret.dst_prefix_in) between ca.dst_number_min_length and ca.dst_number_max_length and#012              length(v_ret.src_prefix_in) between ca.src_number_min_length and ca.src_number_max_length and#012              c.enabled and c.customer#012            ORDER BY#012                masklen(ca.ip) DESC,#012                ca.transport_protocol_id is null,#012                length(prefix_range(ca.dst_prefix)) DESC,#012                length(prefix_range(ca.src_prefix)) DESC,#012                ca.pop_id is null,#012                ca.uri_domain is null,#012                ca.to_domain is null,#012                ca.from_domain is null,#012                ca.require_incoming_auth#012            LIMIT 1"#012PL/pgSQL function route_release(integer,integer,smallint,inet,integer,inet,integer,character varying,character varying,character varying,integer,character varying,character varying,integer,character varying,character varying,integer,character varying,character varying,integer,character varying,character varying,inet,integer,smallint,character varying,character varying,character varyi
Apr 19 01:48:09 rtp-sems sems[22486]: PL/pgSQL function route_release(integer,integer,smallint,inet,integer,inet,integer,character varying,character varying,character varying,integer,character varying,character varying,integer,character varying,character varying,integer,character varying,character varying,integer,character varying,character varying,inet,integer,smallint,character varying,character varying,character varyi
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 0: node_id[integer] -> 8[Int]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 1: pop_id[integer] -> 4[Int]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 2: protocol_id[smallint] -> 1[Int]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 3: remote_ip[inet] -> 'public_ip'[CStr]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 4: remote_port[integer] -> 7000[Int]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 5: local_ip[inet] -> 'public_ip'[CStr]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 6: local_port[integer] -> 11000[Int]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 7: from_dsp[varchar] -> 'src_num'[CStr]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 8: from_name[varchar] -> 'src_num'[CStr]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 9: from_domain[varchar] -> 'public_domain'[CStr]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 10: from_port[integer] -> 7000[Int]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 11: to_name[varchar] -> 'dest_num'[CStr]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 12: to_domain[varchar] -> 'public_domain'[CStr]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 13: to_port[integer] -> 7000[Int]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 14: contact_name[varchar] -> 'src_num'[CStr]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 15: contact_domain[varchar] -> 'src_ip'[CStr]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 16: contact_port[integer] -> 5060[Int]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 17: uri_name[varchar] -> 'dest_num'[CStr]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 0: node_id[integer] -> 8[Int]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 18: uri_domain[varchar] -> 'public_domain'[CStr]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:572] ERROR: 19: auth_id[integer] -> [Undef]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:585] ERROR: 20: X-YETI-AUTH[Raw:*] -> [Undef]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:585] ERROR: 21: Diversion[Uri:uri_user] -> [Undef]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:585] ERROR: 22: X-ORIG-IP[Raw:*] -> 'src_ip'[CStr]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:585] ERROR: 23: X-ORIG-PORT[Raw:*] -> '5060'[CStr]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:585] ERROR: 24: X-ORIG-PROTO[Raw:*] -> '1'[CStr]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:585] ERROR: 25: P-Asserted-Identity[Raw:*] -> [Undef]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:585] ERROR: 26: P-Preferred-Identity[Raw:*] -> [Undef]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:585] ERROR: 27: Privacy[Raw:*] -> [Undef]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:585] ERROR: 28: Remote-Party-ID[Raw:*] -> [Undef]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:585] ERROR: 29: RPID-Privacy[Raw:*] -> [Undef]
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:alarms.cpp:56] ERROR: ALARM 0 [management database connections error] RAISED. current: 1
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22545] [yeti:SqlRouter.cpp:383] ERROR: SQL cant get profiles. Drop request
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 1: pop_id[integer] -> 4[Int]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 2: protocol_id[smallint] -> 1[Int]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 3: remote_ip[inet] -> 'public_ip'[CStr]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 4: remote_port[integer] -> 7000[Int]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 5: local_ip[inet] -> 'public_ip'[CStr]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 6: local_port[integer] -> 11000[Int]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 7: from_dsp[varchar] -> 'src_num'[CStr]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 8: from_name[varchar] -> 'src_num'[CStr]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 9: from_domain[varchar] -> 'public_domain'[CStr]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 10: from_port[integer] -> 7000[Int]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 11: to_name[varchar] -> 'dest_num'[CStr]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 12: to_domain[varchar] -> 'public_domain'[CStr]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 13: to_port[integer] -> 7000[Int]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 14: contact_name[varchar] -> 'src_num'[CStr]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 15: contact_domain[varchar] -> 'src_ip'[CStr]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 16: contact_port[integer] -> 5060[Int]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 17: uri_name[varchar] -> 'dest_num'[CStr]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 18: uri_domain[varchar] -> 'public_domain'[CStr]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:572] ERROR: 19: auth_id[integer] -> [Undef]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:585] ERROR: 20: X-YETI-AUTH[Raw:*] -> [Undef]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:585] ERROR: 21: Diversion[Uri:uri_user] -> [Undef]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:585] ERROR: 22: X-ORIG-IP[Raw:*] -> 'src_ip'[CStr]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:585] ERROR: 23: X-ORIG-PORT[Raw:*] -> '5060'[CStr]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:585] ERROR: 24: X-ORIG-PROTO[Raw:*] -> '1'[CStr]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:585] ERROR: 25: P-Asserted-Identity[Raw:*] -> [Undef]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:585] ERROR: 26: P-Preferred-Identity[Raw:*] -> [Undef]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:585] ERROR: 27: Privacy[Raw:*] -> [Undef]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:585] ERROR: 28: Remote-Party-ID[Raw:*] -> [Undef]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:585] ERROR: 29: RPID-Privacy[Raw:*] -> [Undef]
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:364] DEBUG: GetProfile exception on  SQLThread: fatal = 1 code  = '124'
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:alarms.cpp:56] ERROR: ALARM 0 [management database connections error] RAISED. current: 1
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:db/PgConnectionPool.cpp:151] DEBUG: : Now 1 inactive connections
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SqlRouter.cpp:383] ERROR: SQL cant get profiles. Drop request
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:cdr/Cdr.cpp:104] DEBUG: Cdr[0x7fc130010f10]()
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:cdr/Cdr.cpp:150] DEBUG: Cdr[0x7fc130010f10](profile = 0x7fc13000efc0)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:cdr/Cdr.cpp:178] DEBUG: Cdr::update_sql(SqlCallProfile)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:SBC.cpp:254] DEBUG: PROFILING: get profiles took 0.032761
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:CodesTranslator.cpp:346] DEBUG: translate_db_code: 124, override_id: 0
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:CodesTranslator.cpp:334] DEBUG: translation result: internal = <500:'db base exception'>, response = <500:'Internal Server Error'>, silently_drop = 0, store_cdr = 1
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:cdr/Cdr.cpp:426] DEBUG: Cdr[0x7fc130010f10]::update_internal_reason(initiator = 0,reason = 'db base exception',code = 500) cdr.disconnect_initiator_writed = 0
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:cdr/Cdr.cpp:306] DEBUG: Cdr::update_with_action(act = End)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:cdr/Cdr.cpp:412] DEBUG: Cdr::update_aleg_reason(reason = 'Internal Server Error',code = 500)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:cdr/Cdr.cpp:200] DEBUG: Cdr::update_with_sip_request(AmSipRequest)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:cdr/Cdr.cpp:191] DEBUG: Cdr::update_sbc(SBCCallProfile)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/trans_layer.cpp:449] DEBUG: reply_len = 613
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/trans_layer.cpp:624] DEBUG: Sending to public_ip:7000 <SIP/2.0 500 Internal Server Error#015#012Record-Route: <...>
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/udp_trsp.cpp:289] DEBUG: send msg via UDP from public_ip:11000 to public_ip:7000#012--++--#012SIP/2.0 500 Internal Server Error#015#012Record-Route: <sip:public_ip:7000;lr;ftag=79127557>#015#012Via: SIP/2.0/UDP public_ip:7000;branch=z9hG4bK279.57600643daabb3ab26430152336f0a23.0#015#012Via: SIP/2.0/UDP src_ip:5060;received=src_ip;branch=z9hG4bK-d8754z-d157a7f486bb4461-1---d8754z-;rport=5060#015#012To: <sip:dest_num@public_domain:7000;transport=UDP>;tag=8-3BC17009-625E14D9000858C1-C79F9700#015#012From: "src_num"<sip:src_num@public_domain:7000;transport=UDP>;tag=79127557#015#012Call-ID: NjNhMGU1ZDI4ZjRlMmQyYmFkMDJlYjhjYzk0MjIyN2E.#015#012CSeq: 1 INVITE#015#012Server: yeti-switch 1.9.20#015#012Content-Length: 0#015#012#015#012--++--
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/trans_layer.cpp:2378] DEBUG: update_uas_reply(t=0x7fc130006dd0)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/sip_trans.cpp:260] DEBUG: New timer of type G at time=12399 (repeated=0)(trans=0x7fc130006dd0)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/sip_trans.cpp:260] DEBUG: New timer of type H at time=13974 (repeated=0)(trans=0x7fc130006dd0)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/yeti:cdr/Cdr.cpp:164] DEBUG: ~Cdr[0x7fc130010f10]()
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/AmSessionContainer.cpp:600] DEBUG: onInvite/onRefer returned NULL
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/SipCtrlInterface.cpp:1241] DEBUG: ^^ M [NjNhMGU1ZDI4ZjRlMmQyYmFkMDJlYjhjYzk0MjIyN2E.|] Ru SIP request INVITE handled ^^
Apr 19 01:48:09 rtp-sems sems[22489]: [22532/yeti:db/PgConnectionPool.cpp:250] DEBUG: PgCP: : start connection
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/udp_trsp.cpp:363] DEBUG: vv M [|] u recvd msg via UDP from public_ip:7000 vv#012--++--#012ACK sip:dest_num@public_domain:7000;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP public_ip:7000;branch=z9hG4bK279.57600643daabb3ab26430152336f0a23.0#015#012Max-Forwards: 69#015#012To: <sip:dest_num@public_domain:7000;transport=UDP>;tag=8-3BC17009-625E14D9000858C1-C79F9700#015#012From: "src_num"<sip:src_num@public_domain:7000;transport=UDP>;tag=79127557#015#012Call-ID: NjNhMGU1ZDI4ZjRlMmQyYmFkMDJlYjhjYzk0MjIyN2E.#015#012CSeq: 1 ACK#015#012Content-Length: 0#015#012#015#012--++--
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/parse_uri.cpp:352] DEBUG: Converted URI port (7000) to int (7000)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/parse_via.cpp:548] DEBUG: parsed branch: z9hG4bK279.57600643daabb3ab26430152336f0a23.0
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/parse_via.cpp:571] DEBUG: has_rport: 0
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/trans_table.cpp:99] DEBUG: Matching ACK request
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/trans_table.cpp:118] DEBUG: do_3261_match = 1
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/trans_layer.cpp:1794] DEBUG: ACK matched INVITE transaction 0x7fc130006dd0
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/trans_layer.cpp:2455] DEBUG: update_uas_request(t=0x7fc130006dd0)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/sip_trans.cpp:202] DEBUG: Clearing old timer of type G (timer=0x7fc1580540f0)(trans=0x7fc130006dd0)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/sip_trans.cpp:202] DEBUG: Clearing old timer of type H (timer=0x7fc15806c5d0)(trans=0x7fc130006dd0)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/sip_trans.cpp:260] DEBUG: New timer of type I at time=12624 (repeated=0)(trans=0x7fc130006dd0)
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/trans_layer.cpp:1797] DEBUG: update_uas_request(bucket,t=0x7fc130006dd0,msg) = 6
Apr 19 01:48:09 rtp-sems sems[22489]: [22545/core/sip/trans_layer.cpp:1819] DEBUG: Absorbing non-200-ACK
Apr 19 01:48:09 rtp-sems sems[22489]: [22532/yeti:db/PgConnectionPool.cpp:264] DEBUG: PgCP: : SQL connected. Backend pid: 11572.
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22532] [yeti:alarms.cpp:65] INFO: ALARM 0 [management database connections error] CLEARED
Apr 19 01:48:09 rtp-sems sems[22486]:  [22489/22532] [yeti:db/PgConnectionPool.cpp:310] WARNING: PCP: : All sql connected.
Apr 19 01:48:09 rtp-sems sems[22489]: [22532/yeti:alarms.cpp:65] INFO: ALARM 0 [management database connections error] CLEARED
Apr 19 01:48:09 rtp-sems sems[22489]: [22532/yeti:db/PgConnectionPool.cpp:310] WARNING: PCP: : All sql connected.

rabbani · April 21, 2022, 3:36am

Hey, @dmitry.s is there any way to find out the file path for $libdir/ so that we can manually create it in the slave DB? I ran out of all the options for this test case scenario.
Please advise if there is any other way to can explore and test.
Thanks in advance

dmitry.s · April 21, 2022, 9:43am

You have to install software packages according to documentation Routing database installation — Yeti documentation

rabbani · May 4, 2022, 1:26am

Thanks, @dmitry.s for your help. The problem has been resolved. Much appreciated