CUBE not sending SIP messages properly on the syslog server, only showing SIP ok and OPTIONS

JH51928 · ‎03-12-2021

Hello,

I'm having issues displaying ALL the SIP messages on my Kiwi Syslog server. It will only show a few parts of debug ccsip and ccapi inout, the logs that shows on the syslog server are only OPTIONS and SIP ok, nothing else.

I've followed what TAC told me already but there are lots of messages missing on the syslog server.

Could I ask for your help on this guys, is there something I missed?

Here is the config I've got from TAC

conf t

service timestamps debug datetime local msec

service timestamps log datetime local msec

service sequence

service internal

no logging console

no logging monitor

no logging rate-limit

no logging queue-limit

logging host x.x.x.x

voice iec syslog

logg trap 7

logging buffer 3000000 debug

End

debug voip ccapi inout

debug ccsip messages

Here is example of what showing in the SYSLOG SERVER

11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073844: 10.130.3.1: Received:
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073845: 10.130.3.1: OPTIONS sip:10.0.125.1:5060 SIP/2.0
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073846: 10.130.3.1: Via: SIP/2.0/TCP 10.6.160.12:5060;branch=z9hG4bK62d85fc8045b
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073847: 10.130.3.1: From: <sip:10.6.160.12>;tag=63602335
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073848: 10.130.3.1: To: <sip:10.0.125.1>
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073849: 10.130.3.1: Date: Thu, 11 Mar 2021 04:58:54 GMT
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073850: 10.130.3.1: Call-ID: 79404080-1ec1a029-616b4-ca0060a@10.6.160.12
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073851: 10.130.3.1: User-Agent: Cisco-CUCM12.5
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073852: 10.130.3.1: CSeq: 101 OPTIONS
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073853: 10.130.3.1: Contact: <sip:10.6.160.12:5060;transport=tcp>
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073854: 10.130.3.1: Max-Forwards: 0
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073855: 10.130.3.1: Content-Length: 0
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073856: 10.130.3.1:
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073857: 10.130.3.1: 11261052: Mar 10 23:58:54.828: TCB7FC3EA5A9580 setting property TCP_TOS (11) 7FC3E7B9E578
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073858: 10.130.3.1: 11261053: Mar 10 23:58:54.828: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073859: 10.130.3.1: Sent:
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073860: 10.130.3.1: SIP/2.0 200 OK
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073861: 10.130.3.1: Via: SIP/2.0/TCP 10.6.160.12:5060;branch=z9hG4bK62d85fc8045b
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073862: 10.130.3.1: From: <sip:10.6.160.12>;tag=63602335
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073863: 10.130.3.1: To: <sip:10.0.125.1>;tag=C9C2677C-DE7
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073864: 10.130.3.1: Date: Thu, 11 Mar 2021 04:58:54 GMT
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073865: 10.130.3.1: Call-ID: 79404080-1ec1a029-616b4-ca0060a@10.6.160.12
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073866: 10.130.3.1: Server: Cisco-SIPGateway/IOS-16.7.1
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073867: 10.130.3.1: CSeq: 101 OPTIONS
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073868: 10.130.3.1: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073869: 10.130.3.1: Allow-Events: telephone-event
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073870: 10.130.3.1: Accept: application/sdp
11-03-2021 00:00:01 Local7.Debug 10.130.3.1 34073871: 10.130.3.1: Supported: 100rel,timer,resource-priority,replaces,sdp-
11-03-2021 00:00:02 Local7.Debug 10.130.3.1 34073872: 10.130.3.1: anat
11-03-2021 00:00:02 Local7.Debug 10.130.3.1 34073873: 10.130.3.1: Content-Type: application/sdp
11-03-2021 00:00:02 Local7.Debug 10.130.3.1 34073874: 10.130.3.1: Content-Length: 166
11-03-2021 00:00:02 Local7.Debug 10.130.3.1 34073875: 10.130.3.1:
11-03-2021 00:00:02 Local7.Debug 10.130.3.1 34073876: 10.130.3.1: v=0
11-03-2021 00:00:02 Local7.Debug 10.130.3.1 34073877: 10.130.3.1: o=CiscoSystemsSIP-GW-UserAgent 7623 7165 IN IP4 10.130.30.1
11-03-2021 00:00:02 Local7.Debug 10.130.3.1 34073878: 10.130.3.1: s=SIP Call
11-03-2021 00:00:02 Local7.Debug 10.130.3.1 34073879: 10.130.3.1: c=IN IP4 10.130.30.1
11-03-2021 00:00:02 Local7.Debug 10.130.3.1 34073880: 10.130.3.1: t=0 0
11-03-2021 00:00:02 Local7.Debug 10.130.3.1 34073881: 10.130.3.1: m=audio 0 RTP/AVP 18 0 8 9 4 2 15 3
11-03-2021 00:00:02 Local7.Debug 10.130.3.1 34073882: 10.130.3.1: c=IN IP4 10.130.30.1
11-03-2021 00:00:10 Local7.Debug 10.130.3.1 34073883: 10.130.3.1: 11261054: Mar 10 23:59:02.211: Released port 13319 in Transport Port Agent for TCP IP type 1 delay 240000
11-03-2021 00:00:10 Local7.Debug 10.130.3.1 34073884: 10.130.3.1: 11261055: Mar 10 23:59:02.211: TCP0: state was SYNSENT -> CLOSED [13319 -> 10.6.130.12(2000)]
11-03-2021 00:00:10 Local7.Debug 10.130.3.1 34073885: 10.130.3.1: 11261056: Mar 10 23:59:02.211: TCB 0x7FC3EA5CF830 destroyed
11-03-2021 00:00:19 Local7.Debug 10.130.3.1 34073886: 10.130.3.1: 11261057: Mar 10 23:59:12.212: TCB7FC3EA5CF830 created
11-03-2021 00:00:19 Local7.Debug 10.130.3.1 34073887: 10.130.3.1: 11261058: Mar 10 23:59:12.212: TCB7FC3EA5CF830 setting property TCP_NO_DELAY (0) 7FC3E9E0D3E8
11-03-2021 00:00:19 Local7.Debug 10.130.3.1 34073888: 10.130.3.1: 11261059: Mar 10 23:59:12.212: TCB7FC3EA5CF830 bound to 10.6.125.1.13319
11-03-2021 00:00:19 Local7.Debug 10.130.3.1 34073889: 10.130.3.1: 11261060: Mar 10 23:59:12.212: TCB7FC3EA5CF830 setting property TCP_NONBLOCKING_WRITE (10) 7FC3E9E0D500
11-03-2021 00:00:19 Local7.Debug 10.130.3.1 34073890: 10.130.3.1: 11261061: Mar 10 23:59:12.212: TCB7FC3EA5CF830 setting property TCP_NONBLOCKING_READ (14) 7FC3E9E0D500
11-03-2021 00:00:19 Local7.Debug 10.130.3.1 34073891: 10.130.3.1: 11261062: Mar 10 23:59:12.212: TCB7FC3EA5CF830 setting property TCP_KEEPALIVE (17) 7FC3E9E0D500
11-03-2021 00:00:19 Local7.Debug 10.130.3.1 34073892: 10.130.3.1: 11261063: Mar 10 23:59:12.212: TCP: Setting Keepalive interval and retries to 60 and 4
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073893: 10.130.3.1: 11261064: Mar 10 23:59:12.212: TCB7FC3EA5CF830 setting property TCP_TOS (11) 7FC3E9E0D4F8
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073894: 10.130.3.1: 11261065: Mar 10 23:59:12.212: Reserved port 13319 in Transport Port Agent for TCP IP type 1
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073895: 10.130.3.1: 11261066: Mar 10 23:59:12.213: TCP: sending SYN, seq 1930348372, ack 0
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073896: 10.130.3.1: 11261067: Mar 10 23:59:12.213: TCP0: Connection to 10.6.130.12:2000, advertising MSS 536
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073897: 10.130.3.1: 11261068: Mar 10 23:59:12.213: TCP0: state was CLOSED -> SYNSENT [13319 -> 10.6.130.12(2000)]
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073898: 10.130.3.1: 11261069: Mar 10 23:59:12.570: TCP0: keepalive timeout (0/4)
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073899: 10.130.3.1: 11261070: Mar 10 23:59:13.249: TCB7FC3EAC4A0A0 getting property TCP_VRFTABLEID (20)
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073900: 10.130.3.1: 11261071: Mar 10 23:59:13.249: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073901: 10.130.3.1: Received:
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073902: 10.130.3.1: OPTIONS sip:10.0.125.1:5060 SIP/2.0
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073903: 10.130.3.1: Via: SIP/2.0/TCP 10.6.130.11:5060;branch=z9hG4bK9157b53505d03
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073904: 10.130.3.1: From: <sip:10.6.130.11>;tag=763234174
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073905: 10.130.3.1: To: <sip:10.0.125.1>
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073906: 10.130.3.1: Date: Thu, 11 Mar 2021 04:59:13 GMT
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073907: 10.130.3.1: Call-ID: 84936c00-1ec1a029-91502-b82060a@10.6.130.11
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073908: 10.130.3.1: User-Agent: Cisco-CUCM12.5
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073909: 10.130.3.1: CSeq: 101 OPTIONS
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073910: 10.130.3.1: Contact: <sip:10.6.130.11:5060;transport=tcp>
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073911: 10.130.3.1: Max-Forwards: 0
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073912: 10.130.3.1: Content-Length: 0
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073913: 10.130.3.1:
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073914: 10.130.3.1: 11261072: Mar 10 23:59:13.250: TCB7FC3EAC4A0A0 setting property TCP_TOS (11) 7FC3E7B9E578
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073915: 10.130.3.1: 11261073: Mar 10 23:59:13.251: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073916: 10.130.3.1: Sent:
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073917: 10.130.3.1: SIP/2.0 200 OK
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073918: 10.130.3.1: Via: SIP/2.0/TCP 10.6.130.11:5060;branch=z9hG4bK9157b53505d03
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073919: 10.130.3.1: From: <sip:10.6.130.11>;tag=763234174
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073920: 10.130.3.1: To: <sip:10.0.125.1>;tag=C9C2AF72-196D
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073921: 10.130.3.1: Date: Thu, 11 Mar 2021 04:59:13 GMT
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073922: 10.130.3.1: Call-ID: 84936c00-1ec1a029-91502-b82060a@10.6.130.11
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073923: 10.130.3.1: Server: Cisco-SIPGateway/IOS-16.7.1
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073924: 10.130.3.1: CSeq: 101 OPTIONS
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073925: 10.130.3.1: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073926: 10.130.3.1: Allow-Events: telephone-event
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073927: 10.130.3.1: Accept: application/sdp
11-03-2021 00:00:20 Local7.Debug 10.130.3.1 34073928: 10.130.3.1: Supported: 100rel,timer,resource-priority,replaces,s
11-03-2021 00:00:21 Local7.Debug 10.130.3.1 34073929: 10.130.3.1: dp-anat
11-03-2021 00:00:21 Local7.Debug 10.130.3.1 34073930: 10.130.3.1: Content-Type: application/sdp
11-03-2021 00:00:21 Local7.Debug 10.130.3.1 34073931: 10.130.3.1: Content-Length: 166
11-03-2021 00:00:21 Local7.Debug 10.130.3.1 34073932: 10.130.3.1:
11-03-2021 00:00:21 Local7.Debug 10.130.3.1 34073933: 10.130.3.1: v=0
11-03-2021 00:00:21 Local7.Debug 10.130.3.1 34073934: 10.130.3.1: o=CiscoSystemsSIP-GW-UserAgent 7854 7402 IN IP4 10.130.30.1
11-03-2021 00:00:21 Local7.Debug 10.130.3.1 34073935: 10.130.3.1: s=SIP Call
11-03-2021 00:00:21 Local7.Debug 10.130.3.1 34073936: 10.130.3.1: c=IN IP4 10.130.30.1
11-03-2021 00:00:21 Local7.Debug 10.130.3.1 34073937: 10.130.3.1: t=0 0
11-03-2021 00:00:21 Local7.Debug 10.130.3.1 34073938: 10.130.3.1: m=audio 0 RTP/AVP 18 0 8 9 4 2 15 3
11-03-2021 00:00:21 Local7.Debug 10.130.3.1 34073939: 10.130.3.1: c=IN IP4 10.130.30.1
11-03-2021 00:00:21 Local7.Debug 10.130.3.1 34073940: 10.130.3.1: 11261074: Mar 10 23:59:14.213: TCP0: RETRANS timeout timer expired
11-03-2021 00:00:21 Local7.Debug 10.130.3.1 34073941: 10.130.3.1: 11261075: Mar 10 23:59:14.213: 10.6.125.1:13319 <---> 10.6.130.12:2000 congestion window changes
11-03-2021 00:00:21 Local7.Debug 10.130.3.1 34073942: 10.130.3.1: 11261076: Mar 10 23:59:14.213: cwnd from 536 to 536, ssthresh from 65535 to 1072
11-03-2021 00:00:21 Local7.Debug 10.130.3.1 34073943: 10.130.3.1: 11261077: Mar 10 23:59:14.213: TCP0: timeout #1 - timeout is 4000 ms, seq 1930348372
11-03-2021 00:00:21 Local7.Debug 10.130.3.1 34073944: 10.130.3.1: 11261078: Mar 10 23:59:14.213: TCP: (13319) -> 10.6.130.12(2000)
11-03-2021 00:00:26 Local7.Debug 10.130.3.1 34073945: 10.130.3.1: 11261079: Mar 10 23:59:18.213: TCP0: RETRANS timeout timer expired
11-03-2021 00:00:26 Local7.Debug 10.130.3.1 34073946: 10.130.3.1: 11261080: Mar 10 23:59:18.213: TCP0: timeout #2 - timeout is 8000 ms, seq 1930348372
11-03-2021 00:00:26 Local7.Debug 10.130.3.1 34073947: 10.130.3.1: 11261081: Mar 10 23:59:18.214: TCP: (13319) -> 10.6.130.12(2000)
11-03-2021 00:00:27 Local7.Debug 10.130.3.1 34073948: 10.130.3.1: 11261082: Mar 10 23:59:19.706: TCP0: keepalive timeout (0/4)
11-03-2021 00:00:28 Local7.Debug 10.130.3.1 34073949: 10.130.3.1: 11261083: Mar 10 23:59:21.263: TCB7FC3EA5A8B60 getting property TCP_VRFTABLEID (20)
11-03-2021 00:00:28 Local7.Debug 10.130.3.1 34073950: 10.130.3.1: 11261084: Mar 10 23:59:21.263: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

TONY SMITH · ‎03-15-2021

What does the log on the router show for that time period?

JH51928 · ‎03-18-2021

I don't have information for that time period. I've set no logging on the router.

I just enabled the logging on the console a few minutes ago and it seems okay on the router side.

VON CLAWSON · ‎03-15-2021

Let's see the output for

show debug

show logging

Please rate if this helps.

JH51928 · ‎03-18-2021

SHOW DEBUG

IOSXE Conditional Debug Configs:

Conditional Debug Global State: Stop

IOSXE Packet Tracing Configs:

Packet Infra debugs:

Ip Address Port
------------------------------------------------------|----------

CCAPI:
debug voip ccapi inout is ON (filter is OFF)
CCSIP SPI: SIP Call Message tracing is enabled (filter is OFF)

I'm seeing in the SHOW LOGGING that it displays all the sip messages there.

Due to confidentiality, I couldn't upload the show logging. I could do it but it may take me a while to remove all the confidential details.

It seem to be working on the router side, any ideas?

JH51928 · ‎03-26-2021

HI Everyone,

Sip messages are okay on the router. Maybe Kiwi sip log server is not compatible with CUCM?

JH51928 · ‎03-30-2021

Anyone?

Any help would be appreciated

RichardBooth3236 · ‎08-11-2021

I have this problem too. If I collect the debug directly from the CUBE it is presented properly

When collected from Kiwi Syslog it mangles the output rendering TranslatorX useless.

JH51928 · ‎08-30-2021

Hi Richard, did you manage to fix it?

RichardBooth3236 · ‎08-30-2021

Nope. I gave up. Tried different syslog servers-same issue. If you do manage to sort something please share!