sipcapture / paStash

pastaʃ'ʃ = Spaghetti I/O Event Data Processing, Interpolation, Correlation and beyond :spaghetti:
http://sipcapture.io
Apache License 2.0
101 stars 27 forks source link

Audiocodes SBC syslog #75

Closed spady7 closed 3 years ago

spady7 commented 3 years ago

Hi, I'am trying to send "syslog" coming from Audiocodes SBC to Homer 7. What i did so far is a configuration file for pastash:

`input { udp { host => 0.0.0.0 port => 514 type => syslog } }

output { stdout{} if [rcinfo] != 'undefined' { hep { host => '10.160.21.80' port => 9069 hep_id => 2222 hep_type => 1 } } }`

and i am sending the following output to Homer 7:

[STDOUT] { "message": "<133>[S=1455266] [SID=b9027c:24:167717] (N 5828845) AcSIPDialog(#1532): Handling GENERAL_RESPONSE_REQ in state DialogInitiated \n(N 5828846) States: (#1532)AcSIPDialog[DialogInitiated->DialogConnected] \n(N 5828847) ---- Outgoing SIP Message to 52.114.76.76:12544 from SIPInterface #2 (Teams) TLS TO(#156) SocketID(182) ---- \nSIP/2.0 200 OK \nVia: SIP/2.0/TLS 52.114.76.76:5061;branch=z9hG4bK5e9ae5e1 \nFrom: <sip:sip-du-a-eu.pstnhub.microsoft.com:5061>;tag=d652f27d-dba2-466e-b4a6-c0b6db2fd363 \nTo: <sip:10.160.111.51>;tag=1c345880336 \nCall-ID: 7ac9a01a-9624-41b8-970d-c903c5b24cd5 \nCSeq: 1 OPTIONS \nContact: <sip:sbc.domain.com:5061;transport=tls> \nServer: SBC Lab/v.7.20A.260.012 \nContent-Length: 0 \n \n \n(N 5828848) AcSIPDialog(#1532): Handling DIALOG_DISCONNECT_REQ in state DialogConnected \n(N 5828849) States: (#1532)AcSIPDialog[DialogConnected->DialogDisconnected] \n(N 5828850) RELEASE_ACK_EV: (#117)SIPSBCDialogLeg -> (#23)SBCDialog[Disconnecting->Disconnected] \n -> (#17)SBCEndPoint[Releasing->Released] \n -> (#8)SBCController[Disconnecting->Disconnected] \n -> (#16)SBCEndPoint[Releasing->Released] \n -> (#90)SBCDialog[Disconnecting->Disconnected] \n -> (#113)SIPSBCDialogLeg[Deallocated] \n [Time:17-12@17:08:32.551]", "host": "10.160.21.20", "udp_port": "514", "type": "syslog", "@timestamp": "2020-12-17T15:08:39.891Z", "@version": "1" } [STDOUT] { "message": "<133>[S=1455267] [SID=b9027c:24:167717] (N 5828851) SIPAppMngr::GetControlIPAddress - Near NAT translation found for SIP Interface 2. Translated IP Address 82.185.88.164:5061 \n(N 5828852) States: (#117)SIPSBCDialogLeg[Deallocated] \n(N 5828853) Discarding event SBC_ROUTING_DONE_EV. Receiver is invalid (#127) \n(N 5828854) States: (#57)SBCRoutesIterator[Deallocated] \n (#127)SBCFeature[Deallocated] \n (#8)SBCController[Deallocated] \n(N 5828855) CAC: Remove SBC Outgoing Other, IPG 1 (Teams): 0, SRD 0 (DefaultSRD): 0, SipIF 2 (Teams): 0 \n(N 5828856) States: (#90)SBCCall[Deallocated] \n(N 5828857) CAC: Remove SBC Incoming Other, IPG 1 (Teams): 0, SRD 0 (DefaultSRD): 0, SipIF 2 (Teams): 0 \n(N 5828858) States: (#23)SBCCall[Deallocated] \n [Time:17-12@17:08:32.552]", "host": "10.160.21.20", "udp_port": "514", "type": "syslog", "@timestamp": "2020-12-17T15:08:39.892Z", "@version": "1" } [STDOUT] { "message": "<135>[S=1455268] [BID=b9027c:24] _DnsCallback: end query recieved _GetInterfaceIndexByCtx(ctx) 1, q->qtyp 1 q->name sip-du-a-as.pstnhub.microsoft.com, p.dnsp_ttl 2 [File:DnsApi_Linux.cpp Line:1390] [Time:17-12@17:08:32.560]", "host": "10.160.21.20", "udp_port": "514", "type": "syslog", "@timestamp": "2020-12-17T15:08:39.896Z", "@version": "1" } [STDOUT] { "message": "<135>[S=1455269] [BID=b9027c:24] _DnsUpdateCacheEntryAddrInfo: update addr for query sip-du-a-as.pstnhub.microsoft.com [File:DnsApi_Linux.cpp Line:360] [Time:17-12@17:08:32.560]", "host": "10.160.21.20", "udp_port": "514", "type": "syslog", "@timestamp": "2020-12-17T15:08:39.896Z", "@version": "1" } [STDOUT] { "message": "<135>[S=1455270] [BID=b9027c:24] sip-du-a-as.pstnhub.microsoft.com resolved to 52.114.7.24 [File:DnsApi_Linux.cpp Line:313] [Time:17-12@17:08:32.560]", "host": "10.160.21.20", "udp_port": "514", "type": "syslog", "@timestamp": "2020-12-17T15:08:39.897Z", "@version": "1" }

However I cannot see anything on Homer server. Any help?

Regards

lmangani commented 3 years ago

It's not that simple :) The current attempt will not produce any results. pastash can receive the syslog input, but needs help converting it into a format we can use. The key here is to find a correlation vector from syslog to our realm.

Is there any information in your syslog we can correlate back to a SIP session detail? S? BID? If so, we can build a parser (check out the Ribbon example for a reference) to convert the messages to either SIP HEP (1) or LOG HEP (100) to be sent to Homer. For some products, we look for an internal correlation ID and map it to ephemeral elements which might appear in the flow.

spady7 commented 3 years ago

Yes, we could use [SID=b9027c:24:167717]

It means: b9027c = last 3 byte of MAC ADDRES of SBC 24 = number of reset (reset of SBC) 167717 = ID of the entire call (SIP call).

Can this help you?

spady7 commented 3 years ago

I've attached a 'syslog.txt' file where there is a complete capture of a call. There you can find how syslog output looks like Is that enough to understand?

I really want to help and improve it. Let me know

Il giorno gio 17 dic 2020 alle ore 17:36 Lorenzo Mangani < notifications@github.com> ha scritto:

Could you "pair" this with a SIP message for us to understand? We have no clue what your traffic looks like :)

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/sipcapture/paStash/issues/75#issuecomment-747554998, or unsubscribe https://github.com/notifications/unsubscribe-auth/AHRIEALLR2KF27SOHHPVHP3SVIXRPANCNFSM4U72QSPA .

12:56:33.000 10.160.21.20 local0.notice [S=1428798] [SID=b9027c:24:164757] (N 5725337) (#86)gwSession[Allocated]. Handle:00007FCCBDDC0B78; Global session ID: 6b456e3c0cfee1c1 (N 5725338) (#3):Call Setup Run Rules Set ID 0 (N 5725339) GetTag looking for dialed number: +39987654321 (N 5725340) GetNumber - no match found: +39987654321 (N 5725341) GetTag did not find match. Dialed number: +39987654321 (N 5725342) (#3):Call Setup Run Rule 0: Query Dial Plan for +39987654321 - Not found. (N 5725343) (#3):Call Setup Run Rule 0: Execute condition/action (N 5725344) (#3):Call Setup Run Rule: Execute result:1 (N 5725345) GetTag looking for dialed number: +39987654321 (N 5725346) GetNumber - no match found: +39987654321 (N 5725347) GetTag did not find match. Dialed number: +39987654321 (N 5725348) (#3):Call Setup Run Rule 1: Query Dial Plan for +39987654321 - Not found. (N 5725349) (#3):Call Setup Run Rule 1: Execute condition/action (N 5725350) (#3):Call Setup Run Rule: Execute result:1 (N 5725351) GetTag looking for dialed number: +39123456789 (N 5725352) GetNumber - no match found: +39123456789 (N 5725353) GetTag did not find match. Dialed number: +39123456789 [Time:17-12@12:56:33.125] 12:56:33.000 10.160.21.20 local0.notice [S=1428799] [SID=b9027c:24:164757] (N 5725354) (#3):Call Setup Run Rule 2: Query Dial Plan for +39123456789 - Not found. (N 5725355) (#3):Call Setup Run Rule 2: Execute condition/action (N 5725356) (#3):Call Setup Run Rule: Execute result:1 (N 5725357) GetTag looking for dialed number: +39987654321 (N 5725358) GetNumber - no match found: +39987654321 (N 5725359) GetTag did not find match. Dialed number: +39987654321 (N 5725360) (#3):Call Setup Run Rule 3: Query Dial Plan for +39987654321 - Not found. (N 5725361) (#3):Call Setup Run Rule 3: Execute condition/action (N 5725362) (#3):Call Setup Run Rule: Execute result:1 (N 5725363) GetTag looking for dialed number: +39123456789 (N 5725364) (#3):Call Setup Run Rule 4: Query Dial Plan for +39123456789 - Tags:Entita=ITSP;CallType=TUTTO (N 5725365) (#3):Call Setup Run Rule 4: Execute condition/action (N 5725366) (#3):Call Setup Run Rule: Execute result:1 (N 5725367) Dest Tags after SipInterface CSR: Entita=ITSP;CallType=TUTTO (N 5725368) Condition Table matched on condition Index 0 (N 5725369) Classification Succeeded - Source IP Group #1 (Teams) (N 5725370) GetTag looking for dialed number: +39987654321 [Time:17-12@12:56:33.125] 12:56:33.000 10.160.21.20 local0.notice [S=1428800] [SID=b9027c:24:164757] (N 5725371) GetNumber - no match found: +39987654321 (N 5725372) GetTag did not find match. Dialed number: +39987654321 (N 5725373) GetTag looking for dialed number: +39123456789 (N 5725374) GetNumber - no match found: +39123456789 (N 5725375) GetTag did not find match. Dialed number: +39123456789 (N 5725376) (#4):Call Setup Run Rules Set ID 2 (N 5725377) (#4):Call Setup Run Rule 0: Execute condition/2 actions (N 5725378) (#4):Call Setup Run Rule: Execute result:1 (N 5725379) Dest Tags after Initial CSR: Entita=ITSP;CallType=TUTTO (N 5725380) States: (#196)SBCRoutesIterator[InitialCSRRouting->InitialRouting] (N 5725381) SBCRoutingMngr::GetTagEntity Tag:Entita=ITSP matched with IpGroup 2 (N 5725382) States: (#196)SBCRoutesIterator[InitialRouting->AlternativeRouting] (N 5725383) SBC_ADMIT_DIALOGS_EV: (#196)SBCRoutesIterator -> (#0)SBCAdmissionControlMngr (N 5725384) CAC: Add SBC Incoming INVITE, IPG 1 (Teams): 1, SRD 0 (DefaultSRD): 1, SipIF 2 (Teams): 1 (N 5725385) ResourceCounter: SBC leg +1 [1/6] (N 5725386) CAC: Add SBC Outgoing INVITE, IPG 2 (Oxe-Cloud): 1, SRD 0 (DefaultSRD): 1, SipIF 1 (Oxe-Cloud): 1 (N 5725387) ResourceCounter: SBC leg +1 [2/6] [Time:17-12@12:56:33.125] 12:56:33.000 10.160.21.20 local0.notice [S=1428801] [SID=b9027c:24:164757] (N 5725388) (#196)Route found (5), Route by IPGroup, IP Group 1 -> 2 (Teams -> Oxe-Cloud) (N 5725389) ---- Incoming SIP Message from 52.114.75.24:8577 to SIPInterface #2 (Teams) TLS TO(#90) SocketID(76) ---- [Time:17-12@12:56:33.125] 12:56:33.000 10.160.21.20 local0.notice [S=1428802] [SID=b9027c:24:164757] INVITE sip:+39123456789@sbc.domain.com:5061;user=phone;transport=tls SIP/2.0 FROM: Nome Cognomesip:+39987654321@sip.pstnhub.microsoft.com:5061;user=phone;tag=e2aa9c74944a4411b3791ebcfa3390e6 TO: sip:+39123456789@sbc.domain.com:5061;user=phone CSEQ: 1 INVITE CALL-ID: c795054f08435f14b699a1631d44eb13 MAX-FORWARDS: 70 VIA: SIP/2.0/TLS 52.114.75.24:5061;branch=z9hG4bKbd39feee RECORD-ROUTE: <sip:sip-du-a-eu.pstnhub.microsoft.com:5061;transport=tls;lr> CONTACT: <sip:api-du-c-euwe.pstnhub.microsoft.com:443;x-i=b40e45cc-54db-4f29-8239-1d02ae503cec;x-c=c795054f08435f14b699a1631d44eb13/d/8/a0442fc75495487ea28d3c30e28a77a3> CONTENT-LENGTH: 2207 USER-AGENT: Microsoft.PSTNHub.SIPProxy v.2020.12.7.3 i.EUWE.8 CONTENT-TYPE: application/sdp ALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY P-ASSERTED-IDENTITY: tel:+39987654321>,<sip:nome.cognome@domain.com PRIVACY: id X-MS-UserLocation: external X-MS-MediaPath: sbc.domain.com v=0 o=- 0 0 IN IP4 52.113.200.73 s=session c=IN IP4 52.113.200.73 b=CT:1500 t=0 0 m=audio 53156 RTP/SAVP 104 9 112 111 18 0 8 103 97 13 118 119 101 a=rtcp:53152 a=ice-ufrag:TNKI a=ice-pwd:SIhYxeeyzMV1UDefYf54rhUP a=rtcp-mux a=candidate:4 1 UDP 1258289663 52 [Time:17-12@12:56:33.125] 12:56:33.000 10.160.21.20 local0.notice [S=1428803] [SID=b9027c:24:164757] .113.200.73 53156 typ relay raddr 78.4.222.178 rport 50005 a=candidate:4 2 UDP 1258289150 52.113.200.73 53152 typ relay raddr 78.4.222.178 rport 50007 a=candidate:1 1 UDP 2130706431 10.161.224.204 50006 typ host a=candidate:1 2 UDP 2130705918 10.161.224.204 50007 typ host a=candidate:2 1 tcp-act 2121006078 10.161.224.204 50000 typ host a=candidate:2 2 tcp-act 2121006078 10.161.224.204 50000 typ host a=candidate:3 1 UDP 1694497791 78.4.222.178 50005 typ srflx raddr 10.161.224.204 rport 50005 a=candidate:3 2 UDP 1694497278 78.4.222.178 50007 typ srflx raddr 10.161.224.204 rport 50007 a=candidate:5 1 tcp-act 1684796926 78.4.222.178 50011 typ srflx raddr 10.161.224.204 rport 50011 a=candidate:5 2 tcp-act 1684796926 78.4.222.178 50011 typ srflx raddr 10.161.224.204 rport 50011 a=candidate:6 1 tcp-pass 1248195582 52.113.202.32 52936 typ relay raddr 78.4.222.178 rport 50011 a=candidate:6 2 tcp-pass 1248195582 52.113.202.32 52936 typ relay raddr 78.4.222.178 rport 50011 a=candidate:7 1 tcp-act 1248588286 52.113.202.32 52936 typ relay raddr 78.4.222.178 rport 50011 a=candidate:7 2 tcp-act 1248588286 52.113.202.32 52936 typ relay raddr 78.4.222.178 rport 50011 a=crypto:1 AES_CM_128_HMAC_SHA1_32 in [Time:17-12@12:56:33.125] 12:56:33.000 10.160.21.20 local0.notice [S=1428804] [SID=b9027c:24:164757] line:nXU4LMX2H6l3+MeOSVNHt6jTRa4qOLE1BllYqnx3|2^31 a=crypto:2 AES_CM_128_HMAC_SHA1_80 inline:nXU4LMX2H6l3+MeOSVNHt6jTRa4qOLE1BllYqnx3|2^31 a=crypto:3 AES_CM_128_HMAC_SHA1_80 inline:nXU4LMX2H6l3+MeOSVNHt6jTRa4qOLE1BllYqnx3|2^31|1:1 a=rtpmap:104 SILK/16000 a=fmtp:104 useinbandfec=0; usedtx=0 a=rtpmap:9 G722/8000 a=rtpmap:112 G7221/16000 a=fmtp:112 bitrate=24000 a=rtpmap:111 SIREN/16000 a=fmtp:111 bitrate=16000 a=rtpmap:18 G729/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:103 SILK/8000 a=fmtp:103 useinbandfec=0; usedtx=0 a=rtpmap:97 RED/8000 a=rtpmap:13 CN/8000 a=rtpmap:118 CN/16000 a=rtpmap:119 CN/24000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:200 [Time:17-12@12:56:33.125] 12:56:33.000 10.160.21.20 local0.notice [S=1428805] [BID=b9027c:24] (N 5725335) TLSSocketAPI(#86)::HandleConnectEvent - Local IP Address = 10.160.111.51:5061, Remote IP Address = 52.114.75.24:8577 (N 5725391) TLSSocketAPI(#86)::HandshakeCompleted - TLS handshake success [Time:17-12@12:56:33.125] 12:56:33.000 10.160.21.20 local0.notice [S=1428806] [SID=b9027c:24:164757] (N 5725390) States: (#829)AcSIPCall[Allocated] (N 5725392) SBCNewCallData: (#14)AcSBCCallAPI -> (#14)SIPSBCCallLeg (N 5725393) NEW_CALL_EV: (#14)SIPSBCCallLeg -> (#13)SBCCall[Idle->NewCall] (N 5725394) (#13)SBCCall: Profiled<Tel=-1,Ip=1 (Teams)>: ExtCGrp=0 MSBeh=1 RTCPMod=1 Rmt3xx=2 PlyHeldTn=1 RmtUpdSup=0 RmtRvtSup=1 RmtDOS=0 RmtRB=3 RmtEMS=0 RmtRBSR=1 RmtHF=3 Ice=1 (N 5725395) NEW_CALL_EV: (#13)SBCCall -> (#3)SBCEndPoint[Idle->NewCall] -> (#1)SBCController[Idle->NewCall] -> (#2)SBCEndPoint[Idle->NewCall] -> (#207)CallPlacement -> (#12)SBCCall[Idle->NewCall] (N 5725396) (#12)SBCCall: Profiled<Tel=-1,Ip=2 (Oxe-Cloud)>: DiscOnBrok=0 AllCGrp=0 ACdrM=1 MSBeh=2 Rmt3xx=2 PlyHeldTn=1 AssrtID=1 RmtRB=3 RmtRBSR=1 RmtRepB=1 (N 5725397) NEW_CALL_EV: (#12)SBCCall -> (#101)SIPSBCCallLeg (N 5725398) SIPAppMngr::GetControlIPAddress - Near NAT translation found for SIP Interface 2. Translated IP Address 82.x.x.x:5061 (N 5725399) ReliableTransportObject(#90)::ShouldConnectionBePersistent - Opening persistent connection with proxy: 52.114.75.24:5061(SI=2) (N 5725400) InviteServerTransaction(#949)::SetResponseAddr - Setting ReceivedFromIP as response IP due to configuration [Time:17-12@12:56:33.125] 12:56:33.000 10.160.21.20 local0.notice [S=1428807] [SID=b9027c:24:164757] (N 5725401) AcSIPCall(#829): Handling INVITE in state Idle (N 5725402) AcSIPCall(#829)::UpdateRemoteLocation - Setting ReceivedFrom address as transport object's key 52.114.75.24:5061 (N 5725403) AcTransactionUser::CheckRemoteAddressChange - Remote is behind the NAT (N 5725404) States: (#829)AcSIPCall[Idle->Invited] (N 5725405) SBCSetupData: (#14)AcSBCCallAPI -> (#14)SIPSBCCallLeg (N 5725406) States: (#14)SBCOfferAnswerMngr[Idle->Offered] (N 5725407) (#5)MediaStream[Allocated] (#5)MediaStream belongs to call #13 (N 5725408) AllocateAddress: Allocated address port 8028 IntIPv4 1 IntIPv6 -1 extension 1 (N 5725409) MapLocalMediaIpPort - Translated media port 10.160.111.51:8028 to 82.x.x.x:8028 (N 5725410) (#13)ChannelResource::AllocateMediaIpPorts RealmIndex(2) port(8028) Allocated. (N 5725411) AcSIPCall(#829): Handling TRYING_REQ in state Invited (N 5725412) ---- Outgoing SIP Message to 52.114.75.24:8577 from SIPInterface #2 (Teams) TLS TO(#90) SocketID(76) ---- [Time:17-12@12:56:33.126] 12:56:33.000 10.160.21.20 local0.notice [S=1428808] [SID=b9027c:24:164757] SIP/2.0 100 Trying Via: SIP/2.0/TLS 52.114.75.24:5061;branch=z9hG4bKbd39feee From: "Nome Cognome" sip:+39987654321@sip.pstnhub.microsoft.com:5061;user=phone;tag=e2aa9c74944a4411b3791ebcfa3390e6 To: sip:+39123456789@sbc.domain.com:5061;user=phone Call-ID: c795054f08435f14b699a1631d44eb13 CSeq: 1 INVITE Server: SBC/v.7.20A.260.012 Content-Length: 0 (N 5725413) SETUP_EV: (#14)SIPSBCCallLeg -> (#13)SBCCall (N 5725414) SIPAppMngr::GetControlIPAddress - Near NAT translation found for SIP Interface 2. Translated IP Address 82.x.x.x:5061 (N 5725415) States: (#13)SBCCall[NewCall->Initiated] (N 5725416) SETUP_EV: (#13)SBCCall -> (#3)SBCEndPoint[NewCall->Initiated] -> (#1)SBCController[NewCall->Establishing] -> (#2)SBCEndPoint[NewCall->Initiated] -> (#207)CallPlacement[Idle->Initiated] -> (#12)SBCCall (N 5725417) IP2IPOutboundManipulation Rule #1 (N 5725418) SBCRoutingMngr::OutboundManipulateHosts: Destination host was changed from sbc.domain.com to 10.160.21.200 (N 5725419) States: (#12)SBCCall[NewCall->Initiated] (N 5725420) SETUP_EV: (#12)SBCCall -> (#101)SIPSBCCallLeg (N 5725421) SIPSBCCallLeg(#101) - Route by dest IPGroup: #2 [Time:17-12@12:56:33.126] 12:56:33.000 10.160.21.20 local0.notice [S=1428809] [SID=b9027c:24:164757] (N 5725422) States: (#820)AcSIPCall[Allocated] (#101)SBCOfferAnswerMngr[Idle->Offering] (N 5725423) (#4)MediaStream[Allocated] (#4)MediaStream belongs to call #12 (N 5725424) SBCSDPSecurityFeature(index = 1, type = AUDIO, tag = -100) - new state: Wait_For_Extend (N 5725425) MRC::AllocateMediaResources (N 5725426) ConnectionData::CalculateResourcesForRTPForwarding Leading:NONE Opposite:NONE MediationLevel:RTP (N 5725427) ConnectionData::CalculateResourcesForSRTP Leading:NONE Opposite:SRTP MediationLevel:RTP (N 5725428) SBCSDPSecurityFeature(index = 0, type = AUDIO, tag = -100) - new state: Idle (N 5725429) SBCSDPCodersFeature::PerformCodersPreference - Put in order audio coders according to allowed coders (N 5725430) SBCSDPSecurityFeature(index = 1, type = AUDIO, tag = -100) - new state: Offer_Extended (N 5725431) AllocateAddress: Allocated address port 7028 IntIPv4 0 IntIPv6 -1 extension 1 (N 5725432) (#12)ChannelResource::AllocateMediaIpPorts RealmIndex(1) port(7028) Allocated. (N 5725433) AcSIPCall(#820): Handling SETUP_REQ in state Idle (N 5725434) States: (#820)AcSIPCall[Idle->Inviting] [Time:17-12@12:56:33.127] 12:56:33.000 10.160.21.20 local0.notice [S=1428810] [SID=b9027c:24:164757] (N 5725435) UdpRtxMngr::Transmit 1 INVITE Rtx Left: 6 Dest: 10.160.21.200:5060, TU: AcSIPCall(#820) (N 5725436) ---- Outgoing SIP Message to 10.160.21.200:5060 from SIPInterface #1 (Oxe-Cloud) UDP TO(#1) ---- [Time:17-12@12:56:33.127] 12:56:33.000 10.160.21.20 local0.notice [S=1428811] [SID=b9027c:24:164757] INVITE sip:0123456789@10.160.21.200;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.160.21.20:5062;branch=z9hG4bKac1927888866 Max-Forwards: 69 From: "Nome Cognome" sip:+39987654321@sip.pstnhub.microsoft.com:5061;user=phone;tag=1c1201215409 To: sip:0123456789@10.160.21.200;user=phone Call-ID: 144754610917122020125633@10.160.21.20 CSeq: 1 INVITE Contact: <sip:10.160.21.20:5062;x-i=b40e45cc-54db-4f29-8239-1d02ae503cec;x-c=c795054f08435f14b699a1631d44eb13/d/8/a0442fc75495487ea28d3c30e28a77a3> Supported: sdp-anat Allow: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY User-Agent: SBC/v.7.20A.260.012 P-Asserted-Identity: <tel:+39987654321> P-Asserted-Identity: sip:nome.cognome@domain.com X-MS-UserLocation: External Content-Type: application/sdp Content-Length: 689 v=0 o=- 1760810766 1135981213 IN IP4 10.160.21.20 s=session c=IN IP4 10.160.21.20 b=CT:1500 t=0 0 m=audio 7028 RTP/AVP 8 18 112 111 9 0 104 103 97 118 119 13 101 a=rtcp:7029 a=rtpmap:104 SILK/16000 a=fmtp:104 useinbandfec=0; usedtx=0 a=rtpmap:9 G722/8000 a=rtpmap:112 G7221/16000 a=fmtp:112 bitrate=24000 a=rtpmap:111 SIREN/16000 a=fmtp:111 bitrate=16000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rt [Time:17-12@12:56:33.127] 12:56:33.000 10.160.21.20 local0.notice [S=1428812] [SID=b9027c:24:164757] pmap:103 SILK/8000 a=fmtp:103 useinbandfec=0; usedtx=0 a=rtpmap:97 RED/8000 a=rtpmap:13 CN/8000 a=rtpmap:118 CN/16000 a=rtpmap:119 CN/24000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:200 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=yes [Time:17-12@12:56:33.127] 12:56:33.000 10.160.21.20 local0.notice [S=1428813] [SID=b9027c:24:164757] (N 5725437) ---- Incoming SIP Message from 10.160.21.200:5060 to SIPInterface #1 (Oxe-Cloud) UDP TO(#1) ---- SIP/2.0 100 Trying To: sip:0123456789@10.160.21.200;user=phone From: "Nome Cognome" sip:+39987654321@sip.pstnhub.microsoft.com:5061;user=phone;tag=1c1201215409 Call-ID: 144754610917122020125633@10.160.21.20 CSeq: 1 INVITE Via: SIP/2.0/UDP 10.160.21.20:5062;branch=z9hG4bKac1927888866 Content-Length: 0 (N 5725438) UdpRtxMngr::Remove 1 INVITE, TU: AcSIPCall(#820) (N 5725439) AcSIPCall(#820): Handling 100 in state Inviting (N 5725440) States: (#820)AcSIPCall[Inviting->Proceeding] [Time:17-12@12:56:33.143] 12:56:34.000 10.160.21.20 local0.notice [S=1428814] [SID=b9027c:24:164757] (N 5725441) ---- Incoming SIP Message from 10.160.21.200:5060 to SIPInterface #1 (Oxe-Cloud) UDP TO(#1) ---- SIP/2.0 183 Session Progress Allow: INVITE, ACK, CANCEL, BYE, PRACK, NOTIFY, REFER, SUBSCRIBE, OPTIONS, UPDATE Contact: sip:10.160.21.200 User-Agent: OmniPCX Enterprise R12.1 m2.300.29.a Content-Type: application/sdp To: sip:0123456789@10.160.21.200;user=phone;tag=d69946a2f3a965f398126e5c30fbab3a From: "Nome Cognome" sip:+39987654321@sip.pstnhub.microsoft.com:5061;user=phone;tag=1c1201215409 Call-ID: 144754610917122020125633@10.160.21.20 CSeq: 1 INVITE Via: SIP/2.0/UDP 10.160.21.20:5062;branch=z9hG4bKac1927888866 Content-Length: 240 v=0 o=OXE 1608202591 1608202591 IN IP4 10.160.21.200 s=abs c=IN IP4 10.160.20.30 t=0 0 m=audio 32556 RTP/AVP 18 101 a=sendrecv a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=ptime:20 a=maxptime:40 a=rtpmap:101 telephone-event/8000 (N 5725442) AcSIPCall(#820): Handling 183 in state Proceeding (N 5725443) SBCAlertData: (#101)AcSBCCallAPI -> (#101)SIPSBCCallLeg (N 5725444) States: (#101)SBCOfferAnswerMngr[Offering->Completed] [Time:17-12@12:56:34.416] 12:56:34.000 10.160.21.20 local0.notice [S=1428815] [SID=b9027c:24:164757] (N 5725445) MEDIA_NEGOTIATION_COMPLETED_EV: (#101)SIPSBCCallLeg -> (#12)SBCCall -> (#207)CallPlacement -> (#2)SBCEndPoint -> (#1)SBCController -> (#6)MRC (N 5725446) MRC <- MediaNegotiationCompletedEv Role=FULL_SYNC, NegotiationCause=NONE, Success=True, OriginatorModule=2,IsPreCallConnected= False,Action=ANSWER_RECEIVED,Leading side=1, MMDL ID:(#117) (N 5725447) ResourceCounter: Service channel +1 [1/12] (N 5725448) (#4)RTS::AllocateResource CID 2 Allocated. (N 5725449) ALERT_EV: (#101)SIPSBCCallLeg -> (#12)SBCCall[Initiated->Alerting] -> (#207)CallPlacement -> (#2)SBCEndPoint -> (#1)SBCController -> (#3)SBCEndPoint -> (#13)SBCCall[Initiated->Alerting] -> (#14)SIPSBCCallLeg (N 5725450) MEDIA_ROLE_CHANGED_EV: (#14)SIPSBCCallLeg -> (#13)SBCCall -> (#3)SBCEndPoint -> (#1)SBCController -> (#6)MRC (N 5725451) (#0)StreamsConnector[Allocated] (Leading:(#4)) (N 5725452) ResourceCounter: SBC Media Legs FK +1 [1/6] (N 5725453) (#4)IpTosFieldInUdpPacket: 184 RtpPayload: 18 T38Imm: 0 Activation mode: 1 (N 5725454) (#4)RTS: Coder = 17, Interval = 3, M = 1 (N 5725455) (#4)RTS: CID #2:Channel will be open WITHOUT DSP, Det:Unset [Time:17-12@12:56:34.417] 12:56:34.000 10.160.21.20 local0.notice [S=1428816] [SID=b9027c:24:164757] (N 5725456) #2 OPEN_STREAM (Remote:10.160.20.30:32556, Local:10.160.21.20:7028, Mode:RxOnly, Coder:g72920, Payload:18, RemoteRTCPPort:32557, BrokenTimeout: 10, Red:104, DTMF:gwRFC2833RelayDTMF, Rx:101, Tx:101, FaxTran: 0) (N 5725457) (#4)ChannelConfiguration: [Voice], ConfTypeUpdate = OpenAndActivate (N 5725458) (#12)SBCCall: SetMsa CID 2 with 1 MSAs: 2 0 0 0 0 (N 5725459) (#0)StartSBCSession: CidA: 2(1), Mediation: None, ConnectionType: None, SrcDir: Unknown, DstDir: Unknown (N 5725460) AcSIPCall(#829): Handling ALERT_REQ in state Invited (N 5725461) ---- Outgoing SIP Message to 52.114.75.24:8577 from SIPInterface #2 (Teams) TLS TO(#90) SocketID(76) ---- [Time:17-12@12:56:34.417] 12:56:34.000 10.160.21.20 local0.notice [S=1428817] [SID=b9027c:24:164757] SIP/2.0 180 Ringing Via: SIP/2.0/TLS 52.114.75.24:5061;branch=z9hG4bKbd39feee From: "Nome Cognome" sip:+39987654321@sip.pstnhub.microsoft.com:5061;user=phone;tag=e2aa9c74944a4411b3791ebcfa3390e6 To: sip:+39123456789@sbc.domain.com:5061;user=phone;tag=d69946a2f3a965f398126e5c30fbab3a Call-ID: c795054f08435f14b699a1631d44eb13 CSeq: 1 INVITE Contact: <sip:sbc.domain.com:5061;transport=tls> Record-Route: <sip:sip-du-a-eu.pstnhub.microsoft.com:5061;transport=tls;lr> Allow: INVITE, ACK, CANCEL, BYE, PRACK, NOTIFY, REFER, SUBSCRIBE, OPTIONS, UPDATE Server: SBC/v.7.20A.260.012 Content-Length: 0 [Time:17-12@12:56:34.417] 12:56:34.000 10.160.21.20 local0.notice [S=1428818] [SID=b9027c:24:164757] (N 5725462) recv <--acEV_PCIIF_COMMAND_RESPONSE ch: 2 CmdType: 4 SeqNum: 1 [Time:17-12@12:56:34.419] 12:56:34.000 10.160.21.20 local0.notice [S=1428819] [SID=b9027c:24:164757] (N 5725463) SBC_CMD_RESPONSE_BOARD_EV: (#0)NULL -> (#12)RTPChannelResource [Time:17-12@12:56:34.419] 12:56:34.000 10.160.21.20 local0.notice [S=1428820] [BID=b9027c:24] (N 5725464) recv <-- UnHandled event: EV_ARP_RESOLVED_FOR_CHANNEL (663) [Time:17-12@12:56:34.424] 12:56:34.000 10.160.21.20 local0.notice [S=1428821] [BID=b9027c:24] (N 5725465) recv <-- UnHandled event: EV_ARP_RESOLVED_FOR_CHANNEL (663) [Time:17-12@12:56:34.424] 12:56:41.000 10.160.21.20 local0.notice [S=1428824] [SID=b9027c:24:164757] (N 5725468) ---- Incoming SIP Message from 10.160.21.200:5060 to SIPInterface #1 (Oxe-Cloud) UDP TO(#1) ---- SIP/2.0 200 OK Allow: INVITE, ACK, CANCEL, BYE, PRACK, NOTIFY, REFER, SUBSCRIBE, OPTIONS, UPDATE Contact: sip:10.160.21.200 Supported: replaces,timer,path,100rel User-Agent: OmniPCX Enterprise R12.1 m2.300.29.a Session-Expires: 1800;refresher=uas Content-Type: application/sdp To: sip:0123456789@10.160.21.200;user=phone;tag=d69946a2f3a965f398126e5c30fbab3a From: "Nome Cognome" sip:+39987654321@sip.pstnhub.microsoft.com:5061;user=phone;tag=1c1201215409 Call-ID: 144754610917122020125633@10.160.21.20 CSeq: 1 INVITE Via: SIP/2.0/UDP 10.160.21.20:5062;branch=z9hG4bKac1927888866 Content-Length: 240 v=0 o=OXE 1608202591 1608202591 IN IP4 10.160.21.200 s=abs c=IN IP4 10.160.20.30 t=0 0 m=audio 32556 RTP/AVP 18 101 a=sendrecv a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=ptime:20 a=maxptime:40 a=rtpmap:101 telephone-event/8000 (N 5725469) AcSIPCall(#820): Handling 200 OK in state Proceeding (N 5725470) TU(#820) SIPSessionTimer::SaveSTParams - remote session is enlarging my expires 180 to 1800 [Time:17-12@12:56:40.958] 12:56:41.000 10.160.21.20 local0.notice [S=1428825] [SID=b9027c:24:164757] (N 5725471) States: (#820)AcSIPCall[Proceeding->RemoteAccepted] (N 5725472) SBCConnectData: (#101)AcSBCCallAPI -> (#101)SIPSBCCallLeg (N 5725473) CONNECT_EV: (#101)SIPSBCCallLeg -> (#12)SBCCall[Alerting->Connected] -> (#207)CallPlacement (N 5725474) States: (#196)SBCRoutesIterator[Deallocated] (#207)CallPlacement[Initiated->End] (N 5725475) CONNECT_EV: (#12)SBCCall -> (#2)SBCEndPoint[Initiated->Session] -> (#1)SBCController[Establishing->Active] -> (#3)SBCEndPoint[Initiated->Session] -> (#13)SBCCall[Alerting->Connected] -> (#14)SIPSBCCallLeg (N 5725476) SBCSDPFeatureMngr::PrepareAnswerBeforeResourcesAllocation audio media index = 0. (N 5725477) SBCSDPSecurityFeature::MatchAnswerWithIncomingOffer - SRTP to RTP transcoding is required (MediaIndex = 0). (N 5725478) SBCSDPFeatureMngr::MatchAnswerWithIncomingOffer - Mark of MediaIndex 0 is 1F7. (N 5725479) MRC::AllocateMediaResources (N 5725480) ConnectionData::CalculateResourcesForSRTP Leading:SRTP Opposite:NONE MediationLevel:RTP (N 5725481) ConnectionData::CalculateResourcesForRTPForwarding Leading:NONE Opposite:NONE MediationLevel:RTP [Time:17-12@12:56:40.959] 12:56:41.000 10.160.21.20 local0.notice [S=1428826] [SID=b9027c:24:164757] (N 5725482) SBCSDPFeatureMngr::MatchAndPrepareAnswer - NumOfMatchedAudioMedia = 1. (N 5725483) States: (#14)SBCOfferAnswerMngr[Offered->Completed] (N 5725484) MEDIA_NEGOTIATION_COMPLETED_EV: (#14)SIPSBCCallLeg -> (#13)SBCCall (N 5725485) (#13)Required detectors Unset (N 5725486) MEDIA_NEGOTIATION_COMPLETED_EV: (#13)SBCCall -> (#3)SBCEndPoint -> (#1)SBCController -> (#6)MRC (N 5725487) MRC <- MediaNegotiationCompletedEv Role=DOUBLE_HALF_SYNC, NegotiationCause=NONE, Success=True, OriginatorModule=2,IsPreCallConnected= True,Action=ANSWER_SENT,Leading side=0, MMDL ID:(#114) (N 5725488) ResourceCounter: Service channel +1 [2/12] (N 5725489) (#5)RTS::AllocateResource CID 1 Allocated. (N 5725490) (#13)StreamsConnector[Allocated] (Leading:(#5), Opposite:(#4)) (N 5725491) ConnectionData::CalculateResourcesForSRTP Leading:SRTP Opposite:NONE MediationLevel:RTP (N 5725492) SRTPTunnelingAllowed: False, IsLeadingSideSecured: True, SRTPToRTPStatus: 3 (N 5725493) (#13)StreamsConnector:FreeResources Leading:SRTP Opposite:NONE (N 5725494) ResourceCounter: SBC Media Legs FK +1 [2/6] (N 5725495) (#5)IpTosFieldInUdpPacket: 184 RtpPayload: 18 T38Imm: 0 Activation mode: 1 [Time:17-12@12:56:40.960] 12:56:41.000 10.160.21.20 local0.notice [S=1428827] [SID=b9027c:24:164757] (N 5725496) (#5)RTS: Coder = 17, Interval = 3, M = 1 (N 5725497) (#5)RTS: StunOnMediaPortsMode=1 IceUsernameLocal=KzsYHp3ZOMlrIpsM IceUsernameRemote=TNKI IcePasswordLocal=53OUIyxs2aM8/gEvZpUOprvJ (N 5725498) (#5)#1:Activated Cipher is 2 (2 == SRTP) Active Crypto-Suite = 1 Local Key = 8ZJTN2qKke+07bhjgmAVYU4TziLWr+uSIe8l/Pl4 Remote Key = nXU4LMX2H6l3+MeOSVNHt6jTRa4qOLE1BllYqnx3 (N 5725499) (#5)RTS: CID #1:Channel will be open WITHOUT DSP, Det:Unset, Mediation: [HeaderNorm ] (N 5725500) #1 OPEN_STREAM (Remote:0.0.0.0:0, Local:10.160.111.51:8028, Mode:TxRx, Coder:g72920, Payload:18, RemoteRTCPPort:0, BrokenTimeout: 100, Red:104, DTMF:gwRFC2833RelayDTMF, Rx:101, Tx:101, FaxTran: 0) (N 5725501) (#5)ChannelConfiguration: [Voice], ConfTypeUpdate = OpenAndActivate (N 5725502) (#13)SBCCall: SetMsa CID 1 with 1 MSAs: 1 0 0 0 0 (N 5725503) (#4)MediaStream::AllocateResource MEDIALEG already Allocated. (N 5725504) (#4)IpTosFieldInUdpPacket: 184 RtpPayload: 18 T38Imm: 0 Activation mode: 1 (N 5725505) (#4)RTS: Coder = 17, Interval = 3, M = 1 (N 5725506) (#4)RTS: CID #2:Channel will be open WITHOUT DSP, Det:Unset, Mediation: [HeaderNorm ] [Time:17-12@12:56:40.960] 12:56:41.000 10.160.21.20 local0.notice [S=1428828] [SID=b9027c:24:164757] (N 5725507) #2 OPEN_STREAM (Remote:10.160.20.30:32556, Local:10.160.21.20:7028, Mode:TxRx, Coder:g72920, Payload:18, RemoteRTCPPort:32557, BrokenTimeout: 100, Red:104, DTMF:gwRFC2833RelayDTMF, Rx:101, Tx:101, FaxTran: 0) (N 5725508) (#4)ChannelConfiguration: [Voice], ConfTypeUpdate = OpenAndActivate (N 5725509) (#12)SBCCall: SetMsa CID 2 with 1 MSAs: 2 0 0 0 0 (N 5725510) (#13)StartSBCSession: CidA: 1(1), CidB: 2(2), Mediation: RTP, ConnectionType: FD, SrcDir: FromNet, DstDir: ToNet (N 5725511) States: (#0)StreamsConnector[Deallocated] (N 5725512) AcSIPCall(#829): Handling CONNECT_REQ in state Invited (N 5725513) ---- Outgoing SIP Message to 52.114.75.24:8577 from SIPInterface #2 (Teams) TLS TO(#90) SocketID(76) ---- [Time:17-12@12:56:40.960] 12:56:41.000 10.160.21.20 local0.notice [S=1428829] [SID=b9027c:24:164757] SIP/2.0 200 OK Via: SIP/2.0/TLS 52.114.75.24:5061;branch=z9hG4bKbd39feee From: "Nome Cognome" sip:+39987654321@sip.pstnhub.microsoft.com:5061;user=phone;tag=e2aa9c74944a4411b3791ebcfa3390e6 To: sip:+39123456789@sbc.domain.com:5061;user=phone;tag=d69946a2f3a965f398126e5c30fbab3a Call-ID: c795054f08435f14b699a1631d44eb13 CSeq: 1 INVITE Contact: <sip:sbc.domain.com:5061;transport=tls> Record-Route: <sip:sip-du-a-eu.pstnhub.microsoft.com:5061;transport=tls;lr> Supported: 100rel,timer,replaces,path,sdp-anat Allow: INVITE, ACK, CANCEL, BYE, PRACK, NOTIFY, REFER, SUBSCRIBE, OPTIONS, UPDATE Session-Expires: 1800;refresher=uas Server: SBC/v.7.20A.260.012 Content-Type: application/sdp Content-Length: 549 v=0 o=OXE 1643872722 1955545371 IN IP4 82.x.x.x s=abs c=IN IP4 82.x.x.x t=0 0 a=ice-lite m=audio 8028 RTP/SAVP 18 101 a=ptime:20 a=sendrecv a=ice-ufrag:KzsYHp3ZOMlrIpsM a=ice-pwd:53OUIyxs2aM8/gEvZpUOprvJ a=candidate:508808363 1 udp 2130706431 82.x.x.x 8028 typ host a=candidate:508808363 2 udp 2130706430 82.x.x.x 8029 typ host a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15,16 a=crypto:3 AES_CM [Time:17-12@12:56:40.960] 12:56:41.000 10.160.21.20 local0.notice [S=1428830] [SID=b9027c:24:164757] _128_HMAC_SHA1_80 inline:8ZJTN2qKke+07bhjgmAVYU4TziLWr+uSIe8l/Pl4|2^31 [Time:17-12@12:56:40.960] 12:56:41.000 10.160.21.20 local0.notice [S=1428831] [SID=b9027c:24:164757] (N 5725514) States: (#829)AcSIPCall[Invited->LocalAccepted] (N 5725515) MEDIA_SYNC_ENDED_EV: (#1)SBCController -> (#3)SBCEndPoint -> (#13)SBCCall (N 5725516) MEDIA_SYNC_ENDED_EV: (#1)SBCController -> (#2)SBCEndPoint -> (#12)SBCCall (N 5725517) States: (#207)SBCFeature[Deallocated] [Time:17-12@12:56:40.960] 12:56:41.000 10.160.21.20 local0.notice [S=1428832] [SID=b9027c:24:164757] (N 5725518) recv <--acEV_PCIIF_COMMAND_RESPONSE ch: 1 CmdType: 164 SeqNum: 1 [Time:17-12@12:56:40.965] 12:56:41.000 10.160.21.20 local0.notice [S=1428833] [SID=b9027c:24:164757] (N 5725519) recv <--acEV_PCIIF_COMMAND_RESPONSE ch: 2 CmdType: 164 SeqNum: 2 [Time:17-12@12:56:40.965] 12:56:41.000 10.160.21.20 local0.notice [S=1428834] [SID=b9027c:24:164757] (N 5725520) recv <-- acEV_ALL_RTCP_STATISTICS Ch:2 [Time:17-12@12:56:40.965] 12:56:41.000 10.160.21.20 local0.notice [S=1428835] [SID=b9027c:24:164757] (N 5725521) SBC_CMD_RESPONSE_BOARD_EV: (#0)NULL -> (#13)RTPChannelResource (N 5725522) SBC_CMD_RESPONSE_BOARD_EV: (#0)NULL -> (#12)RTPChannelResource (N 5725523) SBC_ALL_RTCP_STAT_EV: (#0)NULL -> (#12)RTPChannelResource [Time:17-12@12:56:40.966] 12:56:41.000 10.160.21.20 local0.notice [S=1428836] [BID=b9027c:24] (N 5725524) recv <-- UnHandled event: EV_ARP_RESOLVED_FOR_CHANNEL (663) [Time:17-12@12:56:40.970] 12:56:41.000 10.160.21.20 local0.notice [S=1428837] [BID=b9027c:24] (N 5725525) recv <-- UnHandled event: EV_ARP_RESOLVED_FOR_CHANNEL (663) [Time:17-12@12:56:40.970] 12:56:41.000 10.160.21.20 local0.notice [S=1428838] [BID=b9027c:24] (N 5725526) recv <-- UnHandled event: EV_ARP_RESOLVED_FOR_CHANNEL (663) [Time:17-12@12:56:40.970] 12:56:41.000 10.160.21.20 local0.notice [S=1428839] [BID=b9027c:24] (N 5725527) recv <-- UnHandled event: EV_ARP_RESOLVED_FOR_CHANNEL (663) [Time:17-12@12:56:40.970] 12:56:41.000 10.160.21.20 local0.notice [S=1428840] [SID=b9027c:24:164757] (N 5725528) ---- Incoming SIP Message from 52.114.75.24:8576 to SIPInterface #2 (Teams) TLS TO(#91) SocketID(75) ---- ACK sip:sbc.domain.com:5061;transport=tls SIP/2.0 FROM: Nome Cognomesip:+39987654321@sip.pstnhub.microsoft.com:5061;user=phone;tag=e2aa9c74944a4411b3791ebcfa3390e6 TO: sip:+39123456789@sbc.domain.com:5061;user=phone;tag=d69946a2f3a965f398126e5c30fbab3a CSEQ: 1 ACK CALL-ID: c795054f08435f14b699a1631d44eb13 MAX-FORWARDS: 70 VIA: SIP/2.0/TLS 52.114.75.24:5061;branch=z9hG4bK1ac1939e CONTACT: <sip:api-du-c-euwe.pstnhub.microsoft.com:443;x-i=b40e45cc-54db-4f29-8239-1d02ae503cec;x-c=c795054f08435f14b699a1631d44eb13/d/8/a0442fc75495487ea28d3c30e28a77a3> CONTENT-LENGTH: 0 USER-AGENT: Microsoft.PSTNHub.SIPProxy v.2020.12.7.3 i.EUWE.8

lmangani commented 3 years ago

The SIP parsing part is quite simple and in-line with other syslog extractors we have for Sonus/Ribbon/Avaya/etc. The shortcoming is about the network part - as you can observe, unless I'm missing something else, the logs only reveal the remote IPs and unfortunately never the local IP:PORT of the system handling the traffic- since names cannot be used this is the blocker/challenge to surpass:

Outgoing SIP Message to xx.yy.zz.qq:12544 from SIPInterface #2 (Teams) TLS TO(#156) SocketID(182)

The application would have to be provisioned with an array of IP:PORT equivalents for those Source IP Group aliases.

lmangani commented 3 years ago

here's a quick sketch for a possible simplistic parser

Outbound Regex:

(.*)---- Outgoing SIP Message to (.*) from SIPInterface #[0-99] \((.*)\) (.*) TO.*--- \\n(.*)\\n \\n \\n(.*) \[Time:(.*)-(.*)@(.*)\]

Inbound Regex:

(.*)---- Incoming SIP Message from (.*) from SIPInterface #[0-99] \((.*)\) (.*) TO.*--- \\n(.*)\\n \\n \\n(.*) \[Time:(.*)-(.*)@(.*)\]

I'll try hack a quick plugin together for you to modify and extend with real events.

lmangani commented 3 years ago

@spady7 happy hacking: https://github.com/sipcapture/paStash/blob/next/plugins/filters/app_audiocodes/app_audiocodes.md

spady7 commented 3 years ago

Hi Lorenzo and thanks for your help. Now output seams much more better

[Time:18-12@00:31:45.106] [Thu, 17 Dec 2020 22:31:55 GMT] ERROR <133>[S=1499920] [SID=b9027c:24:172873] (N 6009286) SIPAuthenticationMngr::FindChallengeData - Resource SIPChallengeData(#801) was located - (Nonce - ODg2Mzg3NzU1OjMzNTgzNDQ2Mg==) (N 6009287) ---- Incoming SIP Message from 10.160.21.21:5060 to SIPInterface #3 (ATA) UDP TO(#3) ---- REGISTER sip:10.160.21.20 SIP/2.0 Via: SIP/2.0/UDP 10.160.21.21:5060;branch=z9hG4bKac1510967002 Max-Forwards: 70 From: sip:5597@10.160.21.21;tag=1c1510892171 To: sip:5597@10.160.21.21 Call-ID: 814992674121201816210@10.160.21.21 CSeq: 85988 REGISTER Contact: sip:5597@10.160.21.21:5060;expires=180 Authorization: Digest username="5597",realm="DefaultSipRealm",nc=00000001,nonce="ODg2Mzg3NzU1OjMzNTgzNDQ2Mg==",cnonce="Default_Cnonce",uri="sip:10.160.21.20",qop=auth,algorithm=MD5,response="e0e968a622abbe63a451e71328bfcfb7"

Supported: path Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE

Expires: 180 User-Agent: MP-114 FXS/v.6.60A.360.004 Content-Length: 0

(N 6009288) States: (#249)AcSIPDialog[Allocated] (N 6009289) SBCNewCallData: (#80)AcSBCRegisterAPI -> (#80)SIPSBCRegisterLeg (N 6009290) B2BRegistrationInstance(#2)::RegistrationProcessStarted - Number of processes now is 1 [Time:18-12@00:31:45.137] [Thu, 17 Dec 2020 22:31:55 GMT] ERROR <133>[S=1499922] [SID=b9027c:24:172873] (N 6009302) SETUP_EV: (#84)SBCDialog -> (#10)SIPSBCOutgoingRegisterLeg (N 6009303) CONNECT_EV: (#10)SIPSBCOutgoingRegisterLeg -> (#84)SBCDialog[Initiated->Connected] -> (#129)CallPlacement (N 6009304) States: (#261)SBCRoutesIterator[Deallocated] (#129)CallPlacement[Initiated->End] (N 6009305) CONNECT_EV: (#84)SBCDialog -> (#18)SBCEndPoint[Initiated->Session] -> (#9)SBCController[Establishing->Active] -> (#19)SBCEndPoint[Initiated->Session] -> (#35)SBCDialog[Initiated->Connected] -> (#80)SIPSBCRegisterLeg (N 6009306) AcSIPDialog(#249): Handling GENERAL_RESPONSE_REQ in state DialogInitiated (N 6009307) States: (#249)AcSIPDialog[DialogInitiated->DialogConnected] (N 6009308) ---- Outgoing SIP Message to 10.160.21.21:5060 from SIPInterface #3 (ATA) UDP TO(#3) ---- [Time:18-12@00:31:45.138]

but on Homer i cannot see anything.

What is wrong?

Il giorno gio 17 dic 2020 alle ore 20:25 Lorenzo Mangani < notifications@github.com> ha scritto:

@spady7 https://github.com/spady7 happy hacking: https://github.com/sipcapture/paStash/blob/next/plugins/filters/app_audiocodes/app_audiocodes.md

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/sipcapture/paStash/issues/75#issuecomment-747648481, or unsubscribe https://github.com/notifications/unsubscribe-auth/AHRIEALM3DFFVIUWDP4YGUTSVJLKTANCNFSM4U72QSPA .

lmangani commented 3 years ago

The output on screen will not be much relevant. Could you show me your full pastash recipe with the new filter? Should be something like so:

input {
  tcp {
    host => 0.0.0.0
    port => 9514
    type => syslog
  }
}

filter {
  app_audiocodes {}
}

output {
  stdout{}
  if [rcinfo] != 'undefined' {
        hep {
          host => '127.0.0.1'
          port => 9060
          hep_id => 2222
          hep_type => 1
        }
  }
}

Mind this is unlikely to work as is, its never been tested and a pure work of theory. You'll have to hack a little :)

lmangani commented 3 years ago

Don't forget you need to also find a way to provide your realms or your SBC will always look as 127.0.0.1:5060 without Aliases. If you provide some examples for the parts i've explained are missing, we might be able to make progress on that too.

spady7 commented 3 years ago

HI, pastash_audiocodes.conf:

input { udp { host => 0.0.0.0 port => 514 type => syslog } }

filter { app_audiocodes {} }

output { stdout{} if [rcinfo] != 'undefined' { hep { host => '10.160.21.80' port => 9069 hep_id => 100 hep_type => 1 } } }

Il giorno gio 17 dic 2020 alle ore 23:58 Lorenzo Mangani < notifications@github.com> ha scritto:

Don't forget you need to also find a way to provide your realms or your SBC will always look as 127.0.0.1:5060 without Aliases. If you provide some examples for the parts i've explained are missing, we might be able to make progress on that too.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/sipcapture/paStash/issues/75#issuecomment-747751753, or unsubscribe https://github.com/notifications/unsubscribe-auth/AHRIEAMEK4RM2YGSE5XVTPTSVKEKJANCNFSM4U72QSPA .

spady7 commented 3 years ago

What i've posted on attached syslog.txt is what Audiocodes outputs on syslog. There is no way to alter outputs. If i well understand what is missing is an Ip address of SBC. It always use a name, like 'Sip Interface #...' Right?

Il giorno gio 17 dic 2020 alle ore 23:58 Lorenzo Mangani < notifications@github.com> ha scritto:

Don't forget you need to also find a way to provide your realms or your SBC will always look as 127.0.0.1:5060 without Aliases. If you provide some examples for the parts i've explained are missing, we might be able to make progress on that too.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/sipcapture/paStash/issues/75#issuecomment-747751753, or unsubscribe https://github.com/notifications/unsubscribe-auth/AHRIEAMEK4RM2YGSE5XVTPTSVKEKJANCNFSM4U72QSPA .

lmangani commented 3 years ago

Ok next run ngrep -W byline port 9069 -d any to check if any HEP messages are being sent. I assume the non-standard port for HEP is your choice, default would be 9060 for HOMER.

The name of the "trunk" or whatever seems to be inside the parenthesis, ATA in this example below possibly?

---- Incoming SIP Message from 10.160.21.21:5060 to SIPInterface #3 (ATA) UDP TO(#3) ----

NOTE: The parsing format of the syslog events and the txt are different enough to cause issues so i'm basing this on the syslog format

spady7 commented 3 years ago

Strange. 'ngrep -W byline port 9069 -d any' outputs nothing.

port 9069 is my choice, yes.

Il giorno ven 18 dic 2020 alle ore 00:12 Lorenzo Mangani < notifications@github.com> ha scritto:

Ok next run ngrep -W byline port 9069 -d any to check if any HEP messages are being sent. I assume the non-standard port for HEP is your choice, default would be 9060 for HOMER.

The name of the "trunk" or whatever seems to be inside the parenthesis, ATA in this example below possibly?

---- Incoming SIP Message from 10.160.21.21:5060 to SIPInterface #3 (ATA) UDP TO(#3) ----

NOTE: The parsing format of the syslog events and the txt are different enough to cause issues so i'm basing this on the syslog format

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/sipcapture/paStash/issues/75#issuecomment-747761718, or unsubscribe https://github.com/notifications/unsubscribe-auth/AHRIEAKVNPVTNJVMDUALFPLSVKF57ANCNFSM4U72QSPA .

lmangani commented 3 years ago

Then the script is failing to parse and we need to debug it further. Do run this for a few minutes with traffic to get us something to work with consistently - check if the file is created it should have the data in the JSON format pastash uses internally.

input {
  udp {
    host => 0.0.0.0
    port => 514
    type => syslog
  }
}

output {
  file {
    path => /tmp/syslog.dump
  }
}

I'll test it domani ;)

spady7 commented 3 years ago

Audiocodes works i bit complicated way. It use 'entities' (like ATA) and to this entity is associated a sip interface and to that sip interface is associated a network interface.

This is way ( i suppose) we cannot see directly IP:PORT on syslog.

But, we could think to put inside 'pastash_audiocodes.conf' a "MAPPING" of that name to an IP:PORT (I know it because i ve configured on Audiocodes sbc).

Does should work?

The name of the "trunk" or whatever seems to be inside the parenthesis, ATA in this example below possibly?

---- Incoming SIP Message from 10.160.21.21:5060 to SIPInterface #3 (ATA) UDP TO(#3) ----

NOTE: The parsing format of the syslog events and the txt are different enough to cause issues so i'm basing this on the syslog format

Il giorno ven 18 dic 2020 alle ore 00:20 Agiftel Longwave agiftel@gmail.com ha scritto:

Strange. 'ngrep -W byline port 9069 -d any' outputs nothing.

port 9069 is my choice, yes.

Il giorno ven 18 dic 2020 alle ore 00:12 Lorenzo Mangani < notifications@github.com> ha scritto:

Ok next run ngrep -W byline port 9069 -d any to check if any HEP messages are being sent. I assume the non-standard port for HEP is your choice, default would be 9060 for HOMER.

The name of the "trunk" or whatever seems to be inside the parenthesis, ATA in this example below possibly?

---- Incoming SIP Message from 10.160.21.21:5060 to SIPInterface #3 (ATA) UDP TO(#3) ----

NOTE: The parsing format of the syslog events and the txt are different enough to cause issues so i'm basing this on the syslog format

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/sipcapture/paStash/issues/75#issuecomment-747761718, or unsubscribe https://github.com/notifications/unsubscribe-auth/AHRIEAKVNPVTNJVMDUALFPLSVKF57ANCNFSM4U72QSPA .

lmangani commented 3 years ago

We will end up adding some custom config to the filter eventually, but first we need to parse this right. It's a step by step process. I see some other IPs in the logs referring to interfaces, but only you can tell us what's relevant and what's not.

spady7 commented 3 years ago

File is created but is not in JSON format at all. It looks like the same as output on cli console.

here a snippet of file output:

[Time:18-12@01:33:23.753]

<133>[S=1506269] [SID=b9027c:24:173590] (N 6034578) (#12)gwSession[Deallocated] [Time:18-12@01:33:23.768] <135>[S=1506270] [BID=b9027c:24] DnsGetAddrInfo: CacheEntry == NULL ai_family[2] [File:DnsApi_Linux.cpp Line:1690] [Time:18-12@01:33:23.904] <135>[S=1506271] [BID=b9027c:24] _DnsSendQuery status 8 [File:DnsApi_Linux.cpp Line:1430] [Time:18-12@01:33:23.904] <133>[S=1506272] [BID=b9027c:24] (N 6034579) SIPServersIPList::ResolveDNS (ProxySet 2) - Starting resolution of sip.pstnhub.microsoft.com (N 6034580) HandleARecordQuery - Host:sip.pstnhub.microsoft.com is not in cache, setting timer [Time:18-12@01:33:23.904] <135>[S=1506273] [BID=b9027c:24] _DnsCallback: end query recieved _GetInterfaceIndexByCtx(ctx) 1, q->qtyp 1 q->name sip.pstnhub.microsoft.com, p.dnsp_ttl 7 [File:DnsApi_Linux.cpp Line:1390] [Time:18-12@01:33:23.931] <135>[S=1506274] [BID=b9027c:24] _DnsUpdateCacheEntryAddrInfo: update addr for query sip.pstnhub.microsoft.com [File:DnsApi_Linux.cpp Line:360] [Time:18-12@01:33:23.931] <135>[S=1506275] [BID=b9027c:24] sip.pstnhub.microsoft.com resolved to 52.114.76.76 [File:DnsApi_Linux.cpp Line:313] [Time:18-12@01:33:23.931] <135>[S=1506276] [BID=b9027c:24] DnsGetAddrInfo: hostname exists in cache sin_family[2] IPAddr[0x34724c4c] [File:DnsApi_Linux.cpp Line:1743] [Time:18-12@01:33:23.964] <135>[S=1506277] [BID=b9027c:24] DnsGetAddrInfo: CacheEntry == NULL ai_family[2] [File:DnsApi_Linux.cpp Line:1690] [Time:18-12@01:33:23.964] <135>[S=1506278] [BID=b9027c:24] _DnsSendQuery status 8 [File:DnsApi_Linux.cpp Line:1430] [Time:18-12@01:33:23.964] <133>[S=1506279] [BID=b9027c:24] (N 6034581) DNSResolver::HandleTimerExpiredOnWaitForARecord: host: sip.pstnhub.microsoft.com (N 6034582) DNSResolver::HandleTimerExpOnWaitARecord - Host: sip.pstnhub.microsoft.com resolved in external table (N 6034583) SIPServersIPList::AddResolvedProxiesIPToList (ProxySet 2) - sip.pstnhub.microsoft.com was resolved by DNS to 52.114.76.76 (N 6034584) SIPServersIPList::ResolveDNS (ProxySet 2) - Starting resolution of sip2.pstnhub.microsoft.com (N 6034585) HandleARecordQuery - Host:sip2.pstnhub.microsoft.com is not in cache, setting timer [Time:18-12@01:33:23.965] <135>[S=1506280] [BID=b9027c:24] _DnsCallback: end query recieved _GetInterfaceIndexByCtx(ctx) 1, q->qtyp 1 q->name sip2.pstnhub.microsoft.com, p.dnsp_ttl 5 [File:DnsApi_Linux.cpp Line:1390] [Time:18-12@01:33:24.025] <135>[S=1506281] [BID=b9027c:24] _DnsUpdateCacheEntryAddrInfo: update addr for query sip2.pstnhub.microsoft.com [File:DnsApi_Linux.cpp Line:360] [Time:18-12@01:33:24.025] <135>[S=1506282] [BID=b9027c:24] sip2.pstnhub.microsoft.com resolved to 52.114.132.46 [File:DnsApi_Linux.cpp Line:313] [Time:18-12@01:33:24.025] <135>[S=1506283] [BID=b9027c:24] DnsGetAddrInfo: hostname exists in cache sin_family[2] IPAddr[0x3472842e] [File:DnsApi_Linux.cpp Line:1743] [Time:18-12@01:33:24.025] <135>[S=1506284] [BID=b9027c:24] DnsGetAddrInfo: CacheEntry == NULL ai_family[2] [File:DnsApi_Linux.cpp Line:1690] [Time:18-12@01:33:24.025] <135>[S=1506285] [BID=b9027c:24] _DnsSendQuery status 8 [File:DnsApi_Linux.cpp Line:1430] [Time:18-12@01:33:24.025] <133>[S=1506286] [BID=b9027c:24] (N 6034586) DNSResolver::HandleTimerExpiredOnWaitForARecord: host: sip2.pstnhub.microsoft.com (N 6034587) DNSResolver::HandleTimerExpOnWaitARecord - Host: sip2.pstnhub.microsoft.com resolved in external table (N 6034588) SIPServersIPList::AddResolvedProxiesIPToList (ProxySet 2) - sip2.pstnhub.microsoft.com was resolved by DNS to 52.114.132.46 (N 6034589) SIPServersIPList::ResolveDNS (ProxySet 2) - Starting resolution of sip3.pstnhub.microsoft.com (N 6034590) HandleARecordQuery - Host:sip3.pstnhub.microsoft.com is not in cache, setting timer [Time:18-12@01:33:24.025] <135>[S=1506287] [BID=b9027c:24] _DnsCallback: end query recieved _GetInterfaceIndexByCtx(ctx) 1, q->qtyp 1 q->name sip3.pstnhub.microsoft.com, p.dnsp_ttl 4 [File:DnsApi_Linux.cpp Line:1390] [Time:18-12@01:33:24.085] <135>[S=1506288] [BID=b9027c:24] _DnsUpdateCacheEntryAddrInfo: update addr for query sip3.pstnhub.microsoft.com [File:DnsApi_Linux.cpp Line:360] [Time:18-12@01:33:24.085] <135>[S=1506289] [BID=b9027c:24] sip3.pstnhub.microsoft.com resolved to 52.114.7.24 [File:DnsApi_Linux.cpp Line:313] [Time:18-12@01:33:24.085] <135>[S=1506290] [BID=b9027c:24] DnsGetAddrInfo: hostname exists in cache sin_family[2] IPAddr[0x34720718] [File:DnsApi_Linux.cpp Line:1743] [Time:18-12@01:33:24.086] <133>[S=1506291] [BID=b9027c:24] (N 6034591) DNSResolver::HandleTimerExpiredOnWaitForARecord: host: sip3.pstnhub.microsoft.com (N 6034592) DNSResolver::HandleTimerExpOnWaitARecord - Host: sip3.pstnhub.microsoft.com resolved in external table (N 6034593) SIPServersIPList::AddResolvedProxiesIPToList (ProxySet 2) - sip3.pstnhub.microsoft.com was resolved by DNS to 52.114.7.24 (N 6034594) SIPServersIPList::UpdateList (ProxySet 2) - Update process finished [Time:18-12@01:33:24.086] <133>[S=1506292] [SID=b9027c:24:173586] (N 6034595) States: (#1277)AcSIPCall[Disconnected->Idle] (#1277)AcSIPCall[Deallocated] [Time:18-12@01:33:27.502] <133>[S=1506293] [SID=b9027c:24:173586] (N 6034596) (#1)gwSession[Deallocated] [Time:18-12@01:33:27.502] <133>[S=1506294] [SID=b9027c:24:173591] (N 6034597) (#130)gwSession[Allocated]. Handle:00007FCCBDDC0338; Global session ID: 9b0473e38959a95a (N 6034598) SIPEntity::PrepareConfigurationData: Setting persistent connection to proxy: 52.114.132.46:5061 (N 6034599) SIPAppMngr::GetControlIPAddress - Near NAT translation found for SIP Interface 2. Translated IP Address 82.185.88.164:5061 (N 6034600) States: (#1260)AcSIPDialog[Allocated] (N 6034601) AcSIPDialog(#1260): Handling DIALOG_INIT_REQ in state DialogIdle (N 6034602) States: (#1260)AcSIPDialog[DialogIdle->DialogInitiated] (N 6034603) AcSIPDialog(#1260): Handling GENERAL_REQ in state DialogInitiated (N 6034604) ---- Outgoing SIP Message to 52.114.132.46:5061 from SIPInterface #2 (Teams) TLS TO(#10) SocketID(168) ---- [Time:18-12@01:33:36.888] <133>[S=1506295] [SID=b9027c:24:173591] OPTIONS sip:10.160.111.51 SIP/2.0 Via: SIP/2.0/TLS sbc.llspa.it:5061;alias;branch=z9hG4bKac109712278 Max-Forwards: 70 From: ;tag=1c1344704966 To: Call-ID: 7878403091812202013336@sbc.llspa.it CSeq: 1 OPTIONS Contact: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE User-Agent: LLSBC Laboratorio/v.7.20A.260.012 Accept: application/sdp, application/simple-message-summary, message/sipfrag Content-Length: 0 [Time:18-12@01:33:36.888] <133>[S=1506296] [SID=b9027c:24:173591] (N 6034605) ---- Incoming SIP Message from 52.114.132.46:5061 to SIPInterface #2 (Teams) TLS TO(#10) SocketID(168) ---- SIP/2.0 200 OK FROM: ;tag=1c1344704966 TO: CSEQ: 1 OPTIONS CALL-ID: 7878403091812202013336@sbc.llspa.it VIA: SIP/2.0/TLS sbc.llspa.it:5061;branch=z9hG4bKac109712278 CONTENT-LENGTH: 0 ALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY SERVER: Microsoft.PSTNHub.SIPProxy v.2020.12.7.3 i.USEA.6 Il giorno ven 18 dic 2020 alle ore 00:23 Lorenzo Mangani < notifications@github.com> ha scritto: > Then the script is failing to parse and we need to debug it further. Do > run this for a few minutes with traffic to get us something to work with > consistently - check if the file is created it should have the data in the > JSON format pastash uses internally. > > input { > udp { > host => 0.0.0.0 > port => 514 > type => syslog > } > } > > output { > file { > path => /tmp/syslog.dump > } > } > > I'll test it domani ;) > > — > You are receiving this because you were mentioned. > Reply to this email directly, view it on GitHub > , > or unsubscribe > > . >
spady7 commented 3 years ago

For now....Buonanotte ;-)

Il giorno ven 18 dic 2020 alle ore 00:37 Agiftel Longwave agiftel@gmail.com ha scritto:

File is created but is not in JSON format at all. It looks like the same as output on cli console.

here a snippet of file output:

[Time:18-12@01:33:23.753]

<133>[S=1506269] [SID=b9027c:24:173590] (N 6034578) (#12)gwSession[Deallocated] [Time:18-12@01:33:23.768] <135>[S=1506270] [BID=b9027c:24] DnsGetAddrInfo: CacheEntry == NULL ai_family[2] [File:DnsApi_Linux.cpp Line:1690] [Time:18-12@01:33:23.904] <135>[S=1506271] [BID=b9027c:24] _DnsSendQuery status 8 [File:DnsApi_Linux.cpp Line:1430] [Time:18-12@01:33:23.904] <133>[S=1506272] [BID=b9027c:24] (N 6034579) SIPServersIPList::ResolveDNS (ProxySet 2) - Starting resolution of sip.pstnhub.microsoft.com (N 6034580) HandleARecordQuery - Host:sip.pstnhub.microsoft.com is not in cache, setting timer [Time:18-12@01:33:23.904] <135>[S=1506273] [BID=b9027c:24] _DnsCallback: end query recieved _GetInterfaceIndexByCtx(ctx) 1, q->qtyp 1 q->name sip.pstnhub.microsoft.com, p.dnsp_ttl 7 [File:DnsApi_Linux.cpp Line:1390] [Time:18-12@01:33:23.931] <135>[S=1506274] [BID=b9027c:24] _DnsUpdateCacheEntryAddrInfo: update addr for query sip.pstnhub.microsoft.com [File:DnsApi_Linux.cpp Line:360] [Time:18-12@01:33:23.931] <135>[S=1506275] [BID=b9027c:24] sip.pstnhub.microsoft.com resolved to 52.114.76.76 [File:DnsApi_Linux.cpp Line:313] [Time:18-12@01:33:23.931] <135>[S=1506276] [BID=b9027c:24] DnsGetAddrInfo: hostname exists in cache sin_family[2] IPAddr[0x34724c4c] [File:DnsApi_Linux.cpp Line:1743] [Time:18-12@01:33:23.964] <135>[S=1506277] [BID=b9027c:24] DnsGetAddrInfo: CacheEntry == NULL ai_family[2] [File:DnsApi_Linux.cpp Line:1690] [Time:18-12@01:33:23.964] <135>[S=1506278] [BID=b9027c:24] _DnsSendQuery status 8 [File:DnsApi_Linux.cpp Line:1430] [Time:18-12@01:33:23.964] <133>[S=1506279] [BID=b9027c:24] (N 6034581) DNSResolver::HandleTimerExpiredOnWaitForARecord: host: sip.pstnhub.microsoft.com (N 6034582) DNSResolver::HandleTimerExpOnWaitARecord - Host: sip.pstnhub.microsoft.com resolved in external table (N 6034583) SIPServersIPList::AddResolvedProxiesIPToList (ProxySet 2) - sip.pstnhub.microsoft.com was resolved by DNS to 52.114.76.76 (N 6034584) SIPServersIPList::ResolveDNS (ProxySet 2) - Starting resolution of sip2.pstnhub.microsoft.com (N 6034585) HandleARecordQuery - Host:sip2.pstnhub.microsoft.com is not in cache, setting timer [Time:18-12@01:33:23.965] <135>[S=1506280] [BID=b9027c:24] _DnsCallback: end query recieved _GetInterfaceIndexByCtx(ctx) 1, q->qtyp 1 q->name sip2.pstnhub.microsoft.com, p.dnsp_ttl 5 [File:DnsApi_Linux.cpp Line:1390] [Time:18-12@01:33:24.025] <135>[S=1506281] [BID=b9027c:24] _DnsUpdateCacheEntryAddrInfo: update addr for query sip2.pstnhub.microsoft.com [File:DnsApi_Linux.cpp Line:360] [Time:18-12@01:33:24.025] <135>[S=1506282] [BID=b9027c:24] sip2.pstnhub.microsoft.com resolved to 52.114.132.46 [File:DnsApi_Linux.cpp Line:313] [Time:18-12@01:33:24.025] <135>[S=1506283] [BID=b9027c:24] DnsGetAddrInfo: hostname exists in cache sin_family[2] IPAddr[0x3472842e] [File:DnsApi_Linux.cpp Line:1743] [Time:18-12@01:33:24.025] <135>[S=1506284] [BID=b9027c:24] DnsGetAddrInfo: CacheEntry == NULL ai_family[2] [File:DnsApi_Linux.cpp Line:1690] [Time:18-12@01:33:24.025] <135>[S=1506285] [BID=b9027c:24] _DnsSendQuery status 8 [File:DnsApi_Linux.cpp Line:1430] [Time:18-12@01:33:24.025] <133>[S=1506286] [BID=b9027c:24] (N 6034586) DNSResolver::HandleTimerExpiredOnWaitForARecord: host: sip2.pstnhub.microsoft.com (N 6034587) DNSResolver::HandleTimerExpOnWaitARecord - Host: sip2.pstnhub.microsoft.com resolved in external table (N 6034588) SIPServersIPList::AddResolvedProxiesIPToList (ProxySet 2) - sip2.pstnhub.microsoft.com was resolved by DNS to 52.114.132.46 (N 6034589) SIPServersIPList::ResolveDNS (ProxySet 2) - Starting resolution of sip3.pstnhub.microsoft.com (N 6034590) HandleARecordQuery - Host:sip3.pstnhub.microsoft.com is not in cache, setting timer [Time:18-12@01:33:24.025] <135>[S=1506287] [BID=b9027c:24] _DnsCallback: end query recieved _GetInterfaceIndexByCtx(ctx) 1, q->qtyp 1 q->name sip3.pstnhub.microsoft.com, p.dnsp_ttl 4 [File:DnsApi_Linux.cpp Line:1390] [Time:18-12@01:33:24.085] <135>[S=1506288] [BID=b9027c:24] _DnsUpdateCacheEntryAddrInfo: update addr for query sip3.pstnhub.microsoft.com [File:DnsApi_Linux.cpp Line:360] [Time:18-12@01:33:24.085] <135>[S=1506289] [BID=b9027c:24] sip3.pstnhub.microsoft.com resolved to 52.114.7.24 [File:DnsApi_Linux.cpp Line:313] [Time:18-12@01:33:24.085] <135>[S=1506290] [BID=b9027c:24] DnsGetAddrInfo: hostname exists in cache sin_family[2] IPAddr[0x34720718] [File:DnsApi_Linux.cpp Line:1743] [Time:18-12@01:33:24.086] <133>[S=1506291] [BID=b9027c:24] (N 6034591) DNSResolver::HandleTimerExpiredOnWaitForARecord: host: sip3.pstnhub.microsoft.com (N 6034592) DNSResolver::HandleTimerExpOnWaitARecord - Host: sip3.pstnhub.microsoft.com resolved in external table (N 6034593) SIPServersIPList::AddResolvedProxiesIPToList (ProxySet 2) - sip3.pstnhub.microsoft.com was resolved by DNS to 52.114.7.24 (N 6034594) SIPServersIPList::UpdateList (ProxySet 2) - Update process finished [Time:18-12@01:33:24.086] <133>[S=1506292] [SID=b9027c:24:173586] (N 6034595) States: (#1277)AcSIPCall[Disconnected->Idle] (#1277)AcSIPCall[Deallocated] [Time:18-12@01:33:27.502] <133>[S=1506293] [SID=b9027c:24:173586] (N 6034596) (#1)gwSession[Deallocated] [Time:18-12@01:33:27.502] <133>[S=1506294] [SID=b9027c:24:173591] (N 6034597) (#130)gwSession[Allocated]. Handle:00007FCCBDDC0338; Global session ID: 9b0473e38959a95a (N 6034598) SIPEntity::PrepareConfigurationData: Setting persistent connection to proxy: 52.114.132.46:5061 (N 6034599) SIPAppMngr::GetControlIPAddress - Near NAT translation found for SIP Interface 2. Translated IP Address 82.185.88.164:5061 (N 6034600) States: (#1260)AcSIPDialog[Allocated] (N 6034601) AcSIPDialog(#1260): Handling DIALOG_INIT_REQ in state DialogIdle (N 6034602) States: (#1260)AcSIPDialog[DialogIdle->DialogInitiated] (N 6034603) AcSIPDialog(#1260): Handling GENERAL_REQ in state DialogInitiated (N 6034604) ---- Outgoing SIP Message to 52.114.132.46:5061 from SIPInterface #2 (Teams) TLS TO(#10) SocketID(168) ---- [Time:18-12@01:33:36.888] <133>[S=1506295] [SID=b9027c:24:173591] OPTIONS sip:10.160.111.51 SIP/2.0 Via: SIP/2.0/TLS sbc.llspa.it:5061;alias;branch=z9hG4bKac109712278 Max-Forwards: 70 From: ;tag=1c1344704966 To: Call-ID: 7878403091812202013336@sbc.llspa.it CSeq: 1 OPTIONS Contact: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE User-Agent: LLSBC Laboratorio/v.7.20A.260.012 Accept: application/sdp, application/simple-message-summary, message/sipfrag Content-Length: 0 [Time:18-12@01:33:36.888] <133>[S=1506296] [SID=b9027c:24:173591] (N 6034605) ---- Incoming SIP Message from 52.114.132.46:5061 to SIPInterface #2 (Teams) TLS TO(#10) SocketID(168) ---- SIP/2.0 200 OK FROM: ;tag=1c1344704966 TO: CSEQ: 1 OPTIONS CALL-ID: 7878403091812202013336@sbc.llspa.it VIA: SIP/2.0/TLS sbc.llspa.it:5061;branch=z9hG4bKac109712278 CONTENT-LENGTH: 0 ALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY SERVER: Microsoft.PSTNHub.SIPProxy v.2020.12.7.3 i.USEA.6 Il giorno ven 18 dic 2020 alle ore 00:23 Lorenzo Mangani < notifications@github.com> ha scritto: > Then the script is failing to parse and we need to debug it further. Do > run this for a few minutes with traffic to get us something to work with > consistently - check if the file is created it should have the data in the > JSON format pastash uses internally. > > input { > udp { > host => 0.0.0.0 > port => 514 > type => syslog > } > } > > output { > file { > path => /tmp/syslog.dump > } > } > > I'll test it domani ;) > > — > You are receiving this because you were mentioned. > Reply to this email directly, view it on GitHub > , > or unsubscribe > > . >
lmangani commented 3 years ago

That's perfect, sorry if I confused you, this will simply allow reimporting it into the JSON format pastash uses. I'll give it a go and let you know what we find out.

lmangani commented 3 years ago

Pushed a new version which SHOULD produce some output, feel free to try it out:

+ @pastash/filter_app_audiocodes@1.0.12

todo:

spady7 commented 3 years ago

Great!!! Now i can see something on Homer server. output is as follows:

[Fri, 18 Dec 2020 21:24:04 GMT] ERROR failed parsing Outgoing SIP

<133>[S=1638002] [SID=b9027c:24:188846] (N 6565994) (#93)gwSession[Allocated]. Handle:00007FCCBDDC0A28; Global session ID: a0846f6b3d23b251 #012(N 6565995) SIPEntity::PrepareConfigurationData: Setting persistent connection to proxy: 52.114.7.24:5061 #012(N 6565996) SIPAppMngr::GetControlIPAddress - Near NAT translation found for SIP Interface 2. Translated IP Address 82.185.88.164:5061 #012(N 6565997) States: (#950)AcSIPDialog[Allocated] #012(N 6565998) AcSIPDialog(#950): Handling DIALOG_INIT_REQ in state DialogIdle #012(N 6565999) States: (#950)AcSIPDialog[DialogIdle->DialogInitiated] #012(N 6566000) AcSIPDialog(#950): Handling GENERAL_REQ in state DialogInitiated #012(N 6566001) ---- Outgoing SIP Message to 52.114.7.24:5061 from SIPInterface #2 (Teams) TLS TO(#33) SocketID(144) ---- #012 [Time:18-12@23:23:53.504] [Fri, 18 Dec 2020 21:24:04 GMT] ERROR failed parsing Incoming SIP <133>[S=1638004] [SID=b9027c:24:188846] (N 6566002) ---- Incoming SIP Message from 52.114.7.24:5061 to SIPInterface #2 (Teams) TLS TO(#33) SocketID(144) ---- #012SIP/2.0 200 OK #012FROM: ;tag=1c952542661 #012TO: #012CSEQ: 1 OPTIONS #012CALL-ID: 27311412818122020232353@sbc.llspa.it #012VIA: SIP/2.0/TLS sbc.llspa.it:5061;branch=z9hG4bKac522660872 #012CONTENT-LENGTH: 0 #012ALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY #012SERVER: Microsoft.PSTNHub.SIPProxy v.2020.12.7.3 i.ASEA.4 #012 #012 #012(N 6566003) AcSIPDialog(#950): Handling 200 OK in state DialogInitiated #012(N 6566004) States: (#950)AcSIPDialog[DialogInitiated->DialogConnected] #012(N 6566005) SIPServersMngr::UpdateSetWithOnlineServer - Added server 52.114.7.24 to working servers list #012(N 6566006) AcSIPDialog(#950): Handling DIALOG_DISCONNECT_REQ in state DialogConnected #012(N 6566007) States: (#950)AcSIPDialog[DialogConnected->DialogDisconnected] #012(N 6566008) SIPAppMngr::FreeDialogAPI - (#119) #012(N 6566009) States: (#950)AcSIPDialog[Deallocated] #012 (#950)AcSIPDialog[DialogDisconnected->DialogIdle] #012 [Time:18-12@23 :23:53.701] [Fri, 18 Dec 2020 21:24:04 GMT] ERROR failed parsing Incoming SIP <133>[S=1638007] [SID=b9027c:24:188847] (N 6566029) SBC_ADMIT_DIALOGS_EV: (#65)SBCRoutesIterator -> (#0)SBCAdmissionControlMngr #012(N 6566030) CAC: Add SBC Incoming Other, IPG 1 (Teams): 1, SRD 0 (DefaultSRD): 1, SipIF 2 (Teams): 1 #012(N 6566031) CAC: Add SBC Outgoing Other, IPG 1 (Teams): 1, SRD 0 (DefaultSRD): 1, SipIF 2 (Teams): 1 #012(N 6566032) (#65)Route found (0), Route by Address, IP Group 1 -> 1 (Teams -> Teams), Url:internal:0; #012(N 6566033) ---- Incoming SIP Message from 52.114.7.24:4800 to SIPInterface #2 (Teams) TLS TO(#5) SocketID(173) ---- #012OPTIONS sip:sbc.llspa.it:5061;transport=tls SIP/2.0 #012FROM: ;tag=783a74b3-f9e7-4ef2-8b4b-896d6b0d05c4 #012TO: #012CSEQ: 1 OPTIONS #012CALL-ID: 1fbdfb30-a06f-4520-84a9-c7a517b3b8ad #012MAX-FORWARDS: 70 #012VIA: SIP/2.0/TLS 52.114.7.24:5061;branch=z9hG4bKd98f7df #012CONTACT: #012CONTENT-LENGTH: 0 #012USER-AGENT: Microsoft.PSTNHub.SIPProxy v.2020.12.7.3 i.ASEA.4 #012ALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY #012 #012 #012(N 6566034) States: (#954)AcSIPDialog[Allocated] #012(N 6566035) SBCNewCallData: (#17)AcSBCDialogAPI -> (#17)SIPSBCDialogLeg #012 [Time:18-12@23:23:53.702] [STDOUT] { "payload": "SIP/2.0 200 OK \r\nVia: SIP/2.0/TLS 52.114.7.24:5061;branch=z9hG4bKd98f7df \r\nFrom: ;tag=783a74b3-f9e7-4ef2-8b4b-896d6b0d05c4 \r\nTo: ;tag=1c363695166 \r\nCall-ID: 1fbdfb30-a06f-4520-84a9-c7a517b3b8ad \r\nCSeq: 1 OPTIONS \r\nContact: \r\nServer: LLSBC Laboratorio/v.7.20A.260.012 \r\nContent-Length: 0 SIP/2.0 200 OK \r\nVia: SIP/2.0/TLS 52.114.7.24:5061;branch=z9hG4bKd98f7df \r\nFrom: ;tag=783a74b3-f9e7-4ef2-8b4b-896d6b0d05c4 \r\nTo: ;tag=1c363695166 \r\nCall-ID: 1fbdfb30-a06f-4520-84a9-c7a517b3b8ad \r\nCSeq: 1 OPTIONS \r\nContact: \r\nServer: LLSBC Laboratorio/v.7.20A.260.012 \r\nContent-Length: 0 \r\n\r\n", "rcinfo": { "type": "HEP", "version": 3, "payload_type": 1, "ip_family": 2, "protocol": 6, "proto_type": 1, "correlation_id": "1fbdfb30-a06f-4520-84a9-c7a517b3b8ad", "srcIp": "127.0.0.1", "srcPort": 5060, "dstIp": "52.114.7.24", "dstPort": "4800", "time_sec": 1608326644520, "time_usec": 0 } } At homer side looks like as attached picture. (as you can see there is 127.0.0.1 and if i chose an call-id to display, there is always just one method or reply. See attached picture) Il giorno ven 18 dic 2020 alle ore 19:53 Lorenzo Mangani < notifications@github.com> ha scritto: > Pushed a new version which SHOULD produce some output, feel free to try it > out: > > + @pastash/filter_app_audiocodes@1.0.12 > > todo: > > - extract and use message timestamp instead of now() > - convert SBC realm to IP:PORT instead of 127.0.0.1:5060 > > — > You are receiving this because you were mentioned. > Reply to this email directly, view it on GitHub > , > or unsubscribe > > . >
lmangani commented 3 years ago

I don't see any picture, you can 'drag' them into the editor and they should upload. This is a good first step. I've based my example only on responses so there might be bugs on the other Incoming messages. Please confirm if this is the case and I'll take a look. Once that's sorted, we can think of how to get the right ports and addresses figured.

lmangani commented 3 years ago
spady7 commented 3 years ago
Schermata 2020-12-18 alle 22 26 27 Schermata 2020-12-18 alle 22 28 44
spady7 commented 3 years ago

Ok done. Can you see them?

Il giorno sab 19 dic 2020 alle ore 00:06 Lorenzo Mangani < notifications@github.com> ha scritto:

I don't see any picture, you can 'drag' them into the editor and they should upload. This is a good first step. I've based my example only on responses so there might be bugs on the other Incoming messages. Please confirm if this is the case and I'll take a look. Once that's sorted, we can think of how to get the right ports and addresses figured.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/sipcapture/paStash/issues/75#issuecomment-748362489, or unsubscribe https://github.com/notifications/unsubscribe-auth/AHRIEANGL2Z4L645MR3EC4LSVPN7ZANCNFSM4U72QSPA .

lmangani commented 3 years ago

The screenshot doesn't tell me anything. This is about looking for and sharing message details such as parsing of Call-IDs being right or wrong, not just clicking once :) You need to look inside a few messages and tell us if its even right. There's nothing more I can do on your behalf here unless you can share a large chunk of data or a full Call-Flow.

adubovikov commented 3 years ago

on the call flow you see only one message, because for that call id only one message exists :-)

spady7 commented 3 years ago

Sorry guys, Maybe it's not clear to me then how this tool really should work. Following an entire call (done now) I report from the CLI what has arrived and how it is shown on Homer's GUI. I expect the whole call-flow to be seen on HOMER (but maybe I misinterpreted and it doesn't have to be), or not? Sorry if I ask you to explain me in a very basic way. Thanks

[Sat, 19 Dec 2020 10:45:06 GMT] ERROR failed parsing Incoming SIP <133>[S=1718460] [SID=b9027c:24:198171] (N 6891676) (#228)Route found (5), Route by IPGroup, IP Group 1 -> 2 (Teams -> Oxe-Cloud) #012(N 6891677) ---- Incoming SIP Message from 52.114.75.24:9024 to SIPInterface #2 (Teams) TLS TO(#138) SocketID(204) ---- #012 [Time:19-12@12:44:54.873] [Sat, 19 Dec 2020 10:45:06 GMT] ERROR failed parsing Outgoing SIP <133>[S=1718465] [SID=b9027c:24:198171] (N 6891688) AcSIPCall(#945)::UpdateRemoteLocation - Setting ReceivedFrom address as transport object's key 52.114.75.24:5061 #012(N 6891689) AcTransactionUser::CheckRemoteAddressChange - Remote is behind the NAT #012(N 6891690) States: (#945)AcSIPCall[Idle->Invited] #012(N 6891691) SBCSetupData: (#32)AcSBCCallAPI -> (#32)SIPSBCCallLeg #012(N 6891692) States: (#32)SBCOfferAnswerMngr[Idle->Offered] #012(N 6891693) (#21)MediaStream[Allocated] (#21)MediaStream belongs to call #7 #012(N 6891694) AllocateAddress: Allocated address port 8068 IntIPv4 1 IntIPv6 -1 extension 1 #012(N 6891695) MapLocalMediaIpPort - Translated media port 10.160.111.51:8068 to 82.185.88.164:8068 #012(N 6891696) (#7)ChannelResource::AllocateMediaIpPorts RealmIndex(2) port(8068) Allocated. #012(N 6891697) AcSIPCall(#945): Handling TRYING_REQ in state Invited #012(N 6891698) ---- Outgoing SIP Message to 52.114.75.24:9024 from SIPInterface #2 (Teams) TLS TO(#138) SocketID(204) ---- #012 [Time:19-12@12:44:54.874] [Sat, 19 Dec 2020 10:45:06 GMT] ERROR failed parsing Outgoing SIP <133>[S=1718468] [SID=b9027c:24:198171] (N 6891721) UdpRtxMngr::Transmit 1 INVITE Rtx Left: 6 Dest: 10.160.21.200:5060, TU: AcSIPCall(#942) #012(N 6891722) ---- Outgoing SIP Message to 10.160.21.200:5060 from SIPInterface #1 (Oxe-Cloud) UDP TO(#1) ---- #012 [Time:19-12@12:44:54.875] [Sat, 19 Dec 2020 10:45:06 GMT] ERROR failed parsing Incoming SIP <133>[S=1718471] [SID=b9027c:24:198171] (N 6891723) ---- Incoming SIP Message from 10.160.21.200:5060 to SIPInterface #1 (Oxe-Cloud) UDP TO(#1) ---- #012SIP/2.0 100 Trying #012To: <sip:00522385011@10.160.21.200;user=phone> #012From: "Antonio Spirandelli" <sip:+390522375550@sip.pstnhub.microsoft.com:5061;user=phone>;tag=1c414268318 #012Call-ID: 111765558019122020124454@10.160.21.20 #012CSeq: 1 INVITE #012Via: SIP/2.0/UDP 10.160.21.20:5062;branch=z9hG4bKac435960060 #012Content-Length: 0 #012 #012 #012(N 6891724) UdpRtxMngr::Remove 1 INVITE, TU: AcSIPCall(#942) #012(N 6891725) AcSIPCall(#942): Handling 100 in state Inviting #012(N 6891726) States: (#942)AcSIPCall[Inviting->Proceeding] #012 [Time:19-12@12:44:54.891] [STDOUT] { "payload": "OPTIONS sip:10.160.21.20 SIP/2.0 \r\nVia: SIP/2.0/UDP 10.160.21.20:5062;branch=z9hG4bKac2110970476 \r\nMax-Forwards: 70 \r\nFrom: <sip:10.160.21.20>;tag=1c831784973 \r\nTo: <sip:10.160.21.20> \r\nCall-ID: 42154736119122020124454@10.160.21.20 \r\nCSeq: 1 OPTIONS \r\nContact: <sip:10.160.21.20:5062> \r\nAllow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE \r\nUser-Agent: LLSBC Laboratorio/v.7.20A.260.012 \r\nAccept: application/sdp, application/simple-message-summary, message/sipfrag \r\nContent-Length: 0 OPTIONS sip:10.160.21.20 SIP/2.0 \r\nVia: SIP/2.0/UDP 10.160.21.20:5062;branch=z9hG4bKac2110970476 \r\nMax-Forwards: 70 \r\nFrom: <sip:10.160.21.20>;tag=1c831784973 \r\nTo: <sip:10.160.21.20> \r\nCall-ID: 42154736119122020124454@10.160.21.20 \r\nCSeq: 1 OPTIONS \r\nContact: <sip:10.160.21.20:5062> \r\nAllow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE \r\nUser-Agent: LLSBC Laboratorio/v.7.20A.260.012 \r\nAccept: application/sdp, application/simple-message-summary, message/sipfrag \r\nContent-Length: 0 \r\n\r\n", "rcinfo": { "type": "HEP", "version": 3, "payload_type": 1, "ip_family": 2, "protocol": 17, "proto_type": 1, "correlation_id": "42154736119122020124454@10.160.21.20", "srcIp": "127.0.0.1", "srcPort": 5060, "dstIp": "10.160.21.200", "dstPort": "5060", "time_sec": 1608374706365, "time_usec": 0 } } [Sat, 19 Dec 2020 10:45:06 GMT] ERROR failed parsing Incoming SIP <133>[S=1718473] [BID=b9027c:24] (N 6891735) ---- Incoming SIP Message from 10.160.21.200:5060 to SIPInterface #1 (Oxe-Cloud) UDP TO(#1) ---- #012SIP/2.0 200 OK #012Allow: INVITE, ACK, CANCEL, BYE, PRACK, NOTIFY, SUBSCRIBE, OPTIONS, UPDATE, INFO #012Contact: sip:10.160.21.200;isfocus #012Supported: timer,path,100rel #012User-Agent: OmniPCX Enterprise R12.1 m2.300.29.a #012To: <sip:10.160.21.20>;tag=d2128354b858191d177e29389ac8df93 #012From: <sip:10.160.21.20>;tag=1c831784973 #012Call-ID: 42154736119122020124454@10.160.21.20 #012CSeq: 1 OPTIONS #012Via: SIP/2.0/UDP 10.160.21.20:5062;branch=z9hG4bKac2110970476 #012Content-Length: 0 #012 #012 #012(N 6891736) UdpRtxMngr::Remove 1 OPTIONS, TU: AcSIPDialog(#951) #012(N 6891737) AcSIPDialog(#951): Handling 200 OK in state DialogInitiated #012(N 6891738) States: (#951)AcSIPDialog[DialogInitiated->DialogConnected] #012(N 6891739) SIPServersMngr::UpdateSetWithOnlineServer - Server 10.160.21.200 already on working servers list #012(N 6891740) AcSIPDialog(#951): Handling DIALOG_DISCONNECT_REQ in state DialogConnected #012(N 6891741) States: (#951)AcSIPDialog[DialogConnected->DialogDisconnected] #012(N 6891742) SIPAppMngr::FreeDialogAPI - (#468) #012 [Time:19-12@12:44:54.968] [Sat, 19 Dec 2020 10:45:08 GMT] ERROR failed parsing Outgoing SIP <133>[S=1718476] [SID=b9027c:24:198173] (N 6891745) (#20)gwSession[Allocated]. Handle:00007FCCBDDC17D8; Global session ID: 53e6936eefa8ca7a #012(N 6891746) SIPEntity::PrepareConfigurationData: Setting persistent connection to proxy: 52.114.75.24:5061 #012(N 6891747) SIPAppMngr::GetControlIPAddress - Near NAT translation found for SIP Interface 2. Translated IP Address 82.185.88.164:5061 #012(N 6891748) States: (#949)AcSIPDialog[Allocated] #012(N 6891749) AcSIPDialog(#949): Handling DIALOG_INIT_REQ in state DialogIdle #012(N 6891750) States: (#949)AcSIPDialog[DialogIdle->DialogInitiated] #012(N 6891751) AcSIPDialog(#949): Handling GENERAL_REQ in state DialogInitiated #012(N 6891752) ---- Outgoing SIP Message to 52.114.75.24:5061 from SIPInterface #2 (Teams) TLS TO(#134) SocketID(200) ---- #012 [Time:19-12@12:44:56.587] [Sat, 19 Dec 2020 10:45:08 GMT] ERROR failed parsing Incoming SIP <133>[S=1718478] [SID=b9027c:24:198173] (N 6891753) ---- Incoming SIP Message from 52.114.75.24:5061 to SIPInterface #2 (Teams) TLS TO(#134) SocketID(200) ---- #012SIP/2.0 200 OK #012FROM: <sip:10.160.111.51>;tag=1c808889852 #012TO: <sip:10.160.111.51> #012CSEQ: 1 OPTIONS #012CALL-ID: 143672392819122020124456@sbc.llspa.it #012VIA: SIP/2.0/TLS sbc.llspa.it:5061;branch=z9hG4bKac1078538236 #012CONTENT-LENGTH: 0 #012ALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY #012SERVER: Microsoft.PSTNHub.SIPProxy v.2020.12.7.3 i.EUWE.9 #012 #012 #012(N 6891754) AcSIPDialog(#949): Handling 200 OK in state DialogInitiated #012(N 6891755) States: (#949)AcSIPDialog[DialogInitiated->DialogConnected] #012(N 6891756) SIPServersMngr::UpdateSetWithOnlineServer - Server 52.114.75.24 already on working servers list #012(N 6891757) AcSIPDialog(#949): Handling DIALOG_DISCONNECT_REQ in state DialogConnected #012(N 6891758) States: (#949)AcSIPDialog[DialogConnected->DialogDisconnected] #012(N 6891759) SIPAppMngr::FreeDialogAPI - (#461) #012(N 6891760) States: (#949)AcSIPDialog[Deallocated] #012 (#949)AcSIPDialog[DialogDisconnected->DialogIdle] #012 [Time:19-12@12:44:56.618] [Sat, 19 Dec 2020 10:45:08 GMT] ERROR failed parsing Incoming SIP <133>[S=1718481] [SID=b9027c:24:198174] (N 6891780) SBC_ADMIT_DIALOGS_EV: (#227)SBCRoutesIterator -> (#0)SBCAdmissionControlMngr #012(N 6891781) CAC: Add SBC Incoming Other, IPG 1 (Teams): 1, SRD 0 (DefaultSRD): 1, SipIF 2 (Teams): 1 #012(N 6891782) CAC: Add SBC Outgoing Other, IPG 1 (Teams): 1, SRD 0 (DefaultSRD): 1, SipIF 2 (Teams): 1 #012(N 6891783) (#227)Route found (0), Route by Address, IP Group 1 -> 1 (Teams -> Teams), Url:internal:0; #012(N 6891784) ---- Incoming SIP Message from 52.114.75.24:6912 to SIPInterface #2 (Teams) TLS TO(#129) SocketID(201) ---- #012OPTIONS sip:sbc.llspa.it:5061;transport=tls SIP/2.0 #012FROM: <sip:sip-du-a-eu.pstnhub.microsoft.com:5061>;tag=05132b06-9198-46ec-b9a3-2e9df77cc592 #012TO: <sip:10.160.111.51> #012CSEQ: 1 OPTIONS #012CALL-ID: 16fc0817-abbe-4b7c-93ab-33dae8af89a7 #012MAX-FORWARDS: 70 #012VIA: SIP/2.0/TLS 52.114.75.24:5061;branch=z9hG4bK8bef4e8 #012CONTACT: <sip:sip-du-a-eu.pstnhub.microsoft.com:5061> #012CONTENT-LENGTH: 0 #012USER-AGENT: Microsoft.PSTNHub.SIPProxy v.2020.12.7.3 i.EUWE.9 #012ALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY #012 #012 #012(N 6891785) States: (#936)AcSIPDialog[Allocated] #012(N 6891786) SBCNewCallData: (#20)AcSBCDialogAPI -> (#20)SIPSBCDialogLeg #012 [Time:19-12@12:44:56.619] [STDOUT] { "payload": "SIP/2.0 200 OK \r\nVia: SIP/2.0/TLS 52.114.75.24:5061;branch=z9hG4bK8bef4e8 \r\nFrom: <sip:sip-du-a-eu.pstnhub.microsoft.com:5061>;tag=05132b06-9198-46ec-b9a3-2e9df77cc592 \r\nTo: <sip:10.160.111.51>;tag=1c823013751 \r\nCall-ID: 16fc0817-abbe-4b7c-93ab-33dae8af89a7 \r\nCSeq: 1 OPTIONS \r\nContact: <sip:sbc.llspa.it:5061;transport=tls> \r\nServer: LLSBC Laboratorio/v.7.20A.260.012 \r\nContent-Length: 0 SIP/2.0 200 OK \r\nVia: SIP/2.0/TLS 52.114.75.24:5061;branch=z9hG4bK8bef4e8 \r\nFrom: <sip:sip-du-a-eu.pstnhub.microsoft.com:5061>;tag=05132b06-9198-46ec-b9a3-2e9df77cc592 \r\nTo: <sip:10.160.111.51>;tag=1c823013751 \r\nCall-ID: 16fc0817-abbe-4b7c-93ab-33dae8af89a7 \r\nCSeq: 1 OPTIONS \r\nContact: <sip:sbc.llspa.it:5061;transport=tls> \r\nServer: LLSBC Laboratorio/v.7.20A.260.012 \r\nContent-Length: 0 \r\n\r\n", "rcinfo": { "type": "HEP", "version": 3, "payload_type": 1, "ip_family": 2, "protocol": 6, "proto_type": 1, "correlation_id": "16fc0817-abbe-4b7c-93ab-33dae8af89a7", "srcIp": "127.0.0.1", "srcPort": 5060, "dstIp": "52.114.75.24", "dstPort": "6912", "time_sec": 1608374708046, "time_usec": 0 } } [Sat, 19 Dec 2020 10:45:11 GMT] ERROR failed parsing Incoming SIP <133>[S=1718491] [SID=b9027c:24:198171] (N 6891824) ---- Incoming SIP Message from 10.160.21.200:5060 to SIPInterface #1 (Oxe-Cloud) UDP TO(#1) ---- #012SIP/2.0 180 Ringing #012Allow: INVITE, ACK, CANCEL, BYE, PRACK, NOTIFY, REFER, SUBSCRIBE, OPTIONS, UPDATE #012Contact: sip:10.160.21.200 #012User-Agent: OmniPCX Enterprise R12.1 m2.300.29.a #012Content-Type: application/sdp #012To: <sip:00522385011@10.160.21.200;user=phone>;tag=633844cd2a52b012e6f0b21c4e950d1d #012From: "Antonio Spirandelli" <sip:+390522375550@sip.pstnhub.microsoft.com:5061;user=phone>;tag=1c414268318 #012Call-ID: 111765558019122020124454@10.160.21.20 #012CSeq: 1 INVITE #012Via: SIP/2.0/UDP 10.160.21.20:5062;branch=z9hG4bKac435960060 #012Content-Length: 240 #012 #012v=0 #012o=OXE 1608374695 1608374695 IN IP4 10.160.21.200 #012s=abs #012c=IN IP4 10.160.20.30 #012t=0 0 #012m=audio 32600 RTP/AVP 18 101 #012a=sendrecv #012a=rtpmap:18 G729/8000 #012a=fmtp:18 annexb=no #012a=ptime:20 #012a=maxptime:40 #012a=rtpmap:101 telephone-event/8000 #012 #012(N 6891825) AcSIPCall(#942): Handling 180 in state Proceeding #012(N 6891826) SBCAlertData: (#86)AcSBCCallAPI -> (#86)SIPSBCCallLeg #012(N 6891827) States: (#86)SBCOfferAnswerMngr[Offering->Completed] #012 [Time:19-12@12:45:00.299] [Sat, 19 Dec 2020 10:45:11 GMT] ERROR failed parsing Outgoing SIP <133>[S=1718493] [SID=b9027c:24:198171] (N 6891839) #6 OPEN_STREAM (Remote:10.160.20.30:32600, Local:10.160.21.20:7068, Mode:RxOnly, Coder:g72920, Payload:18, RemoteRTCPPort:32601, BrokenTimeout: 10, Red:104, DTMF:gwRFC2833RelayDTMF, Rx:101, Tx:101, FaxTran: 0) #012(N 6891840) (#20)ChannelConfiguration: [Voice], ConfTypeUpdate = OpenAndActivate #012(N 6891841) (#6)SBCCall: SetMsa CID 6 with 1 MSAs: 2 0 0 0 0 #012(N 6891842) (#12)StartSBCSession: CidA: 6(1), Mediation: None, ConnectionType: None, SrcDir: Unknown, DstDir: Unknown #012(N 6891843) AcSIPCall(#945): Handling ALERT_REQ in state Invited #012(N 6891844) ---- Outgoing SIP Message to 52.114.75.24:9024 from SIPInterface #2 (Teams) TLS TO(#138) SocketID(204) ---- #012 [Time:19-12@12:45:00.299] [Sat, 19 Dec 2020 10:45:12 GMT] ERROR failed parsing Incoming SIP <133>[S=1718499] [SID=b9027c:24:198171] (N 6891849) ---- Incoming SIP Message from 10.160.21.200:5060 to SIPInterface #1 (Oxe-Cloud) UDP TO(#1) ---- #012SIP/2.0 200 OK #012Allow: INVITE, ACK, CANCEL, BYE, PRACK, NOTIFY, REFER, SUBSCRIBE, OPTIONS, UPDATE #012Contact: sip:10.160.21.200 #012Supported: replaces,timer,path,100rel #012User-Agent: OmniPCX Enterprise R12.1 m2.300.29.a #012Session-Expires: 1800;refresher=uas #012Content-Type: application/sdp #012To: <sip:00522385011@10.160.21.200;user=phone>;tag=633844cd2a52b012e6f0b21c4e950d1d #012From: "Antonio Spirandelli" <sip:+390522375550@sip.pstnhub.microsoft.com:5061;user=phone>;tag=1c414268318 #012Call-ID: 111765558019122020124454@10.160.21.20 #012CSeq: 1 INVITE #012Via: SIP/2.0/UDP 10.160.21.20:5062;branch=z9hG4bKac435960060 #012Content-Length: 240 #012 #012v=0 #012o=OXE 1608374695 1608374695 IN IP4 10.160.21.200 #012s=abs #012c=IN IP4 10.160.20.30 #012t=0 0 #012m=audio 32600 RTP/AVP 18 101 #012a=sendrecv #012a=rtpmap:18 G729/8000 #012a=fmtp:18 annexb=no #012a=ptime:20 #012a=maxptime:40 #012a=rtpmap:101 telephone-event/8000 #012 #012(N 6891850) AcSIPCall(#942): Handling 200 OK in state Proceeding #012(N 6891851) TU(#942) SIPSessionTimer::SaveSTParams - remote session is enlarging my expires 180 to 1800 #012(N 6891852) States: (#942)AcSIPCall[Proceeding->RemoteAccepted] #012 [Time:19-12@12:45:00.709] [Sat, 19 Dec 2020 10:45:12 GMT] ERROR failed parsing Outgoing SIP <133>[S=1718503] [SID=b9027c:24:198171] (N 6891888) #6 OPEN_STREAM (Remote:10.160.20.30:32600, Local:10.160.21.20:7068, Mode:TxRx, Coder:g72920, Payload:18, RemoteRTCPPort:32601, BrokenTimeout: 100, Red:104, DTMF:gwRFC2833RelayDTMF, Rx:101, Tx:101, FaxTran: 0) #012(N 6891889) (#20)ChannelConfiguration: [Voice], ConfTypeUpdate = OpenAndActivate #012(N 6891890) (#6)SBCCall: SetMsa CID 6 with 1 MSAs: 2 0 0 0 0 #012(N 6891891) (#11)StartSBCSession: CidA: 5(1), CidB: 6(2), Mediation: RTP, ConnectionType: FD, SrcDir: FromNet, DstDir: ToNet #012(N 6891892) States: (#12)StreamsConnector[Deallocated] #012(N 6891893) AcSIPCall(#945): Handling CONNECT_REQ in state Invited #012(N 6891894) ---- Outgoing SIP Message to 52.114.75.24:9024 from SIPInterface #2 (Teams) TLS TO(#138) SocketID(204) ---- #012 [Time:19-12@12:45:00.710] [Sat, 19 Dec 2020 10:45:12 GMT] ERROR failed parsing Incoming SIP <133>[S=1718515] [SID=b9027c:24:198171] (N 6891909) ---- Incoming SIP Message from 52.114.75.24:9024 to SIPInterface #2 (Teams) TLS TO(#138) SocketID(204) ---- #012ACK sip:sbc.llspa.it:5061;transport=tls SIP/2.0 #012FROM: Antonio Spirandelli<sip:+390522375550@sip.pstnhub.microsoft.com:5061;user=phone>;tag=51f0c299a9f8494eaf55fddf3590afd1 #012TO: <sip:+390522385011@sbc.llspa.it:5061>;user=phone;tag=633844cd2a52b012e6f0b21c4e950d1d #012CSEQ: 1 ACK #012CALL-ID: f8e538e4bf535025bfdd8c99080cd2ff #012MAX-FORWARDS: 70 #012VIA: SIP/2.0/TLS 52.114.75.24:5061;branch=z9hG4bK8cde9665 #012CONTACT: <sip:api-du-c-euwe.pstnhub.microsoft.com:443;x-i=7924f078-9d30-4ac2-a95f-eeb3b8ea8c26;x-c=f8e538e4bf535025bfdd8c99080cd2ff/d/8/28e93822c4c1493f90f7be836cde3c1e> #012CONTENT-LENGTH: 0 #012USER-AGENT: Microsoft.PSTNHub.SIPProxy v.2020.12.7.3 i.EUWE.8 #012ALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY #012 #012 #012(N 6891910) AcSIPCall(#945): Handling ACK in state LocalAccepted #012(N 6891911) States: (#945)AcSIPCall[LocalAccepted->Connected] #012(N 6891912) SBCAckData: (#32)AcSBCCallAPI -> (#32)SIPSBCCallLeg #012(N 6891913) SIPSBCConnectAckEvent: (#32)SIPSBCCallLeg -> (#7)SBCCall #012(N 6891914) (#7)Required detectors Unset #012 [Time:19-12@12:45:00.741] [Sat, 19 Dec 2020 10:45:12 GMT] ERROR failed parsing Outgoing SIP <133>[S=1718516] [SID=b9027c:24:198171] (N 6891915) SIPAppMngr::GetControlIPAddress - Near NAT translation found for SIP Interface 2. Translated IP Address 82.185.88.164:5061 #012(N 6891916) States: (#7)SBCCall[Connected->ConnectAcknowledged] #012(N 6891917) SIPSBCConnectAckEvent: (#7)SBCCall -> (#51)SBCEndPoint #012 -> (#25)SBCController #012 -> (#50)SBCEndPoint #012 -> (#6)SBCCall #012(N 6891918) (#6)MRA::For coder g729 Not allowed Control Detection #012(N 6891919) States: (#6)SBCCall[Connected->ConnectAcknowledged] #012(N 6891920) SIPSBCConnectAckEvent: (#6)SBCCall -> (#86)SIPSBCCallLeg #012(N 6891921) AcSIPCall(#942): Handling ACK_REQ in state RemoteAccepted #012(N 6891922) States: (#942)AcSIPCall[RemoteAccepted->Connected] #012(N 6891923) ---- Outgoing SIP Message to 10.160.21.200:5060 from SIPInterface #1 (Oxe-Cloud) UDP TO(#1) ---- #012 [Time:19-12@12:45:00.742] [Sat, 19 Dec 2020 10:45:13 GMT] ERROR failed parsing Incoming SIP <133>[S=1718543] [SID=b9027c:24:198171] (N 6891937) ---- Incoming SIP Message from 52.114.75.24:9024 to SIPInterface #2 (Teams) TLS TO(#138) SocketID(204) ---- #012 [Time:19-12@12:45:02.514] [Sat, 19 Dec 2020 10:45:13 GMT] ERROR failed parsing Outgoing SIP <133>[S=1718547] [SID=b9027c:24:198171] (N 6891950) ConnectionData::CalculateResourcesForRTPForwarding Leading:NONE Opposite:NONE MediationLevel:RTP #012(N 6891951) ConnectionData::CalculateResourcesForSRTP Leading:NONE Opposite:SRTP MediationLevel:RTP #012(N 6891952) SBCSDPSecurityFeature(index = 0, type = AUDIO, tag = -100) - new state: Idle #012(N 6891953) SBCSDPCodersFeature::PerformCodersPreference - Put in order audio coders according to allowed coders #012(N 6891954) SBCSDPSecurityFeature(index = 1, type = AUDIO, tag = -100) - new state: Offer_Extended #012(N 6891955) AcSIPCall(#942): Handling REINVITE_REQ in state Connected #012(N 6891956) UdpRtxMngr::Transmit 2 INVITE Rtx Left: 6 Dest: 10.160.21.200:5060, TU: AcSIPCall(#942) #012(N 6891957) ---- Outgoing SIP Message to 10.160.21.200:5060 from SIPInterface #1 (Oxe-Cloud) UDP TO(#1) ---- #012 [Time:19-12@12:45:02.515] [Sat, 19 Dec 2020 10:45:13 GMT] ERROR failed parsing Incoming SIP <133>[S=1718549] [SID=b9027c:24:198171] (N 6891958) ---- Incoming SIP Message from 10.160.21.200:5060 to SIPInterface #1 (Oxe-Cloud) UDP TO(#1) ---- #012SIP/2.0 100 Trying #012To: <sip:00522385011@10.160.21.200;user=phone>;tag=633844cd2a52b012e6f0b21c4e950d1d #012From: "Antonio Spirandelli" <sip:+390522375550@sip.pstnhub.microsoft.com:5061;user=phone>;tag=1c414268318 #012Call-ID: 111765558019122020124454@10.160.21.20 #012CSeq: 2 INVITE #012Via: SIP/2.0/UDP 10.160.21.20:5062;branch=z9hG4bKac1159815029 #012Content-Length: 0 #012 #012 #012(N 6891959) UdpRtxMngr::Remove 2 INVITE, TU: AcSIPCall(#942) #012(N 6891960) AcSIPCall(#942): Handling 100 in state Connected #012(N 6891961) ---- Incoming SIP Message from 10.160.21.200:5060 to SIPInterface #1 (Oxe-Cloud) UDP TO(#1) ---- #012 [Time:19-12@12:45:02.531] [Sat, 19 Dec 2020 10:45:13 GMT] ERROR failed parsing Outgoing SIP <133>[S=1718553] [SID=b9027c:24:198171] (N 6891986) (#19)RTS: CID #5:Channel will be open WITHOUT DSP, Mediation: [HeaderNorm ] #012(N 6891987) #5 OPEN_STREAM (Remote:0.0.0.0:0, Local:10.160.111.51:8068, Mode:TxRx, Coder:g72920, Payload:18, RemoteRTCPPort:0, BrokenTimeout: 100, Red:104, DTMF:gwRFC2833RelayDTMF, Rx:101, Tx:101, FaxTran: 0) #012(N 6891988) (#19)ChannelConfiguration: [Voice], ConfTypeUpdate = OpenAndActivate #012(N 6891989) (#7)SBCCall: SetMsa CID 5 with 1 MSAs: 1 0 0 0 0 #012(N 6891990) (#10)StartSBCSession: CidA: 6(3), CidB: 5(2), Mediation: RTP, ConnectionType: FD, SrcDir: FromNet, DstDir: ToNet #012(N 6891991) States: (#11)StreamsConnector[Deallocated] #012(N 6891992) AcSIPCall(#945): Handling REINVITE_RESPONSE in state Connected #012(N 6891993) ---- Outgoing SIP Message to 52.114.75.24:9024 from SIPInterface #2 (Teams) TLS TO(#138) SocketID(204) ---- #012 [Time:19-12@12:45:02.532] [Sat, 19 Dec 2020 10:45:13 GMT] ERROR failed parsing Incoming SIP <133>[S=1718571] [SID=b9027c:24:198171] (N 6892016) ---- Incoming SIP Message from 52.114.75.24:9024 to SIPInterface #2 (Teams) TLS TO(#138) SocketID(204) ---- #012ACK sip:sbc.llspa.it:5061;transport=tls SIP/2.0 #012FROM: Antonio Spirandelli<sip:+390522375550@sip.pstnhub.microsoft.com:5061;user=phone>;tag=51f0c299a9f8494eaf55fddf3590afd1 #012TO: <sip:+390522385011@sbc.llspa.it:5061>;user=phone;tag=633844cd2a52b012e6f0b21c4e950d1d #012CSEQ: 2 ACK #012CALL-ID: f8e538e4bf535025bfdd8c99080cd2ff #012MAX-FORWARDS: 70 #012VIA: SIP/2.0/TLS 52.114.75.24:5061;branch=z9hG4bK38883577 #012CONTACT: <sip:api-du-c-euwe.pstnhub.microsoft.com:443;x-i=7924f078-9d30-4ac2-a95f-eeb3b8ea8c26;x-c=f8e538e4bf535025bfdd8c99080cd2ff/d/8/28e93822c4c1493f90f7be836cde3c1e> #012CONTENT-LENGTH: 0 #012USER-AGENT: Microsoft.PSTNHub.SIPProxy v.2020.12.7.3 i.EUWE.8 #012ALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY #012 #012 #012(N 6892017) AcSIPCall(#945): Handling ACK in state Connected #012(N 6892018) SBCReinviteAckData: (#32)AcSBCCallAPI -> (#32)SIPSBCCallLeg #012(N 6892019) SIPSBCReinviteAckEvent: (#32)SIPSBCCallLeg -> (#7)SBCCall #012 -> (#51)SBCEndPoint #012 -> (#25)SBCController #012 -> (#50)SBCEndPoint #012 -> (#6)SBCCall #012 -> (#86)SIPSBCCallLeg #012(N 6892020) AcSIPCall(#942): Handling ACK_REQ in state Connected #012 [Time:19-12@12:45:02.563] [STDOUT] { "payload": "ACK sip:10.160.21.200 SIP/2.0 \r\nVia: SIP/2.0/UDP 10.160.21.20:5062;branch=z9hG4bKac1951884303 \r\nMax-Forwards: 69 \r\nFrom: \"Antonio Spirandelli\" <sip:+390522375550@sip.pstnhub.microsoft.com:5061;user=phone>;tag=1c414268318 \r\nTo: <sip:00522385011@10.160.21.200;user=phone>;tag=633844cd2a52b012e6f0b21c4e950d1d \r\nCall-ID: 111765558019122020124454@10.160.21.20 \r\nCSeq: 2 ACK \r\nContact: <sip:10.160.21.20:5062;x-i=7924f078-9d30-4ac2-a95f-eeb3b8ea8c26;x-c=f8e538e4bf535025bfdd8c99080cd2ff/d/8/28e93822c4c1493f90f7be836cde3c1e> \r\nALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY \r\nUser-Agent: LLSBC Laboratorio/v.7.20A.260.012 \r\nContent-Length: 0 ACK sip:10.160.21.200 SIP/2.0 \r\nVia: SIP/2.0/UDP 10.160.21.20:5062;branch=z9hG4bKac1951884303 \r\nMax-Forwards: 69 \r\nFrom: \"Antonio Spirandelli\" <sip:+390522375550@sip.pstnhub.microsoft.com:5061;user=phone>;tag=1c414268318 \r\nTo: <sip:00522385011@10.160.21.200;user=phone>;tag=633844cd2a52b012e6f0b21c4e950d1d \r\nCall-ID: 111765558019122020124454@10.160.21.20 \r\nCSeq: 2 ACK \r\nContact: <sip:10.160.21.20:5062;x-i=7924f078-9d30-4ac2-a95f-eeb3b8ea8c26;x-c=f8e538e4bf535025bfdd8c99080cd2ff/d/8/28e93822c4c1493f90f7be836cde3c1e> \r\nALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY \r\nUser-Agent: LLSBC Laboratorio/v.7.20A.260.012 \r\nContent-Length: 0 \r\n\r\n", "rcinfo": { "type": "HEP", "version": 3, "payload_type": 1, "ip_family": 2, "protocol": 17, "proto_type": 1, "correlation_id": "111765558019122020124454@10.160.21.20", "srcIp": "127.0.0.1", "srcPort": 5060, "dstIp": "10.160.21.200", "dstPort": "5060", "time_sec": 1608374713980, "time_usec": 0 } } [Sat, 19 Dec 2020 10:45:19 GMT] ERROR failed parsing Incoming SIP <133>[S=1718575] [SID=b9027c:24:198171] (N 6892026) ---- Incoming SIP Message from 52.114.75.24:9024 to SIPInterface #2 (Teams) TLS TO(#138) SocketID(204) ---- #012BYE sip:sbc.llspa.it:5061;transport=tls SIP/2.0 #012FROM: Antonio Spirandelli<sip:+390522375550@sip.pstnhub.microsoft.com:5061;user=phone>;tag=51f0c299a9f8494eaf55fddf3590afd1 #012TO: <sip:+390522385011@sbc.llspa.it:5061>;user=phone;tag=633844cd2a52b012e6f0b21c4e950d1d #012CSEQ: 4 BYE #012CALL-ID: f8e538e4bf535025bfdd8c99080cd2ff #012MAX-FORWARDS: 70 #012VIA: SIP/2.0/TLS 52.114.75.24:5061;branch=z9hG4bK7df8648d #012REASON: Q.850;cause=16;text="7924f078-9d30-4ac2-a95f-eeb3b8ea8c26;CallEndReasonLocalUserInitiated" #012CONTACT: <sip:api-du-c-euwe.pstnhub.microsoft.com:443;x-i=7924f078-9d30-4ac2-a95f-eeb3b8ea8c26;x-c=f8e538e4bf535025bfdd8c99080cd2ff/d/8/28e93822c4c1493f90f7be836cde3c1e> #012CONTENT-LENGTH: 0 #012USER-AGENT: Microsoft.PSTNHub.SIPProxy v.2020.12.7.3 i.EUWE.8 #012ALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY #012P-ASSERTED-IDENTITY: <tel:+390522375550>,<sip:antonio.spirandelli@llspa.it> #012PRIVACY: id #012 #012 #012(N 6892027) ServerTransaction(#1251)::SetResponseAddr - Setting ReceivedFromIP as response IP due to configuration #012(N 6892028) AcSIPCall(#945): Handling BYE in state Connected #012 [Time:19-12@12:45:08.107] [Sat, 19 Dec 2020 10:45:19 GMT] ERROR failed parsing Outgoing SIP <133>[S=1718576] [SID=b9027c:24:198171] (N 6892029) States: (#945)AcSIPCall[Connected->Disconnected] #012(N 6892030) SBCDisconnectData: (#32)AcSBCCallAPI -> (#32)SIPSBCCallLeg #012(N 6892031) RELEASE_EV: (#32)SIPSBCCallLeg -> (#7)SBCCall[ConnectAcknowledged->Disconnecting] #012 -> (#51)SBCEndPoint[Session->Releasing] #012 -> (#25)SBCController[Active->Disconnecting] #012 -> (#50)SBCEndPoint[Session->Releasing] #012 -> (#6)SBCCall[ConnectAcknowledged->Disconnecting] #012 -> (#86)SIPSBCCallLeg #012(N 6892032) AcSIPCall(#942): Handling DISCONNECT_REQ in state Connected #012(N 6892033) UdpRtxMngr::Transmit 3 BYE Rtx Left: 6 Dest: 10.160.21.200:5060, TU: AcSIPCall(#942) #012(N 6892034) ---- Outgoing SIP Message to 10.160.21.200:5060 from SIPInterface #1 (Oxe-Cloud) UDP TO(#1) ---- #012 [Time:19-12@12:45:08.107] [Sat, 19 Dec 2020 10:45:19 GMT] ERROR failed parsing Incoming SIP <133>[S=1718578] [SID=b9027c:24:198171] (N 6892036) ---- Incoming SIP Message from 10.160.21.200:5060 to SIPInterface #1 (Oxe-Cloud) UDP TO(#1) ---- #012SIP/2.0 200 OK #012Allow: INVITE, ACK, CANCEL, BYE, PRACK, NOTIFY, REFER, SUBSCRIBE, OPTIONS, UPDATE #012Supported: replaces,timer,path,100rel #012User-Agent: OmniPCX Enterprise R12.1 m2.300.29.a #012To: <sip:00522385011@10.160.21.200;user=phone>;tag=633844cd2a52b012e6f0b21c4e950d1d #012From: "Antonio Spirandelli" <sip:+390522375550@sip.pstnhub.microsoft.com:5061;user=phone>;tag=1c414268318 #012Call-ID: 111765558019122020124454@10.160.21.20 #012CSeq: 3 BYE #012Via: SIP/2.0/UDP 10.160.21.20:5062;branch=z9hG4bKac2131008762 #012Content-Length: 0 #012 #012 #012(N 6892037) UdpRtxMngr::Remove 3 BYE, TU: AcSIPCall(#942) #012(N 6892038) AcSIPCall(#942): Handling 200 OK in state Disconnected #012(N 6892039) States: (#942)AcSIPCall[Disconnected->Idle] #012 (#942)AcSIPCall[Deallocated] #012(N 6892040) SBCDisconnectAckData: (#86)AcSBCCallAPI -> (#86)SIPSBCCallLeg #012(N 6892041) RELEASE_ACK_EV: (#86)SIPSBCCallLeg -> (#6)SBCCall[Disconnecting->Disconnected] #012(N 6892042) (#10)StopSBCSession: DisconnectAndCloseA, CidA 6(4) CidB 5(3) #012(N 6892043) States: (#10)StreamsConnector[Deallocated] #012 [Time:19-12@12:45:08.168] [STDOUT] { "payload": "SIP/2.0 200 OK \r\nVia: SIP/2.0/TLS 52.114.75.24:5061;branch=z9hG4bK7df8648d \r\nFrom: \"Antonio Spirandelli\" <sip:+390522375550@sip.pstnhub.microsoft.com:5061;user=phone>;tag=51f0c299a9f8494eaf55fddf3590afd1 \r\nTo: <sip:+390522385011@sbc.llspa.it:5061;user=phone>;tag=633844cd2a52b012e6f0b21c4e950d1d \r\nCall-ID: f8e538e4bf535025bfdd8c99080cd2ff \r\nCSeq: 4 BYE \r\nSupported: 100rel,timer,replaces,path \r\nAllow: INVITE, ACK, CANCEL, BYE, PRACK, NOTIFY, REFER, SUBSCRIBE, OPTIONS, UPDATE \r\nServer: LLSBC Laboratorio/v.7.20A.260.012 \r\nContent-Length: 0 SIP/2.0 200 OK \r\nVia: SIP/2.0/TLS 52.114.75.24:5061;branch=z9hG4bK7df8648d \r\nFrom: \"Antonio Spirandelli\" <sip:+390522375550@sip.pstnhub.microsoft.com:5061;user=phone>;tag=51f0c299a9f8494eaf55fddf3590afd1 \r\nTo: <sip:+390522385011@sbc.llspa.it:5061;user=phone>;tag=633844cd2a52b012e6f0b21c4e950d1d \r\nCall-ID: f8e538e4bf535025bfdd8c99080cd2ff \r\nCSeq: 4 BYE \r\nSupported: 100rel,timer,replaces,path \r\nAllow: INVITE, ACK, CANCEL, BYE, PRACK, NOTIFY, REFER, SUBSCRIBE, OPTIONS, UPDATE \r\nServer: LLSBC Laboratorio/v.7.20A.260.012 \r\nContent-Length: 0 \r\n\r\n", "rcinfo": { "type": "HEP", "version": 3, "payload_type": 1, "ip_family": 2, "protocol": 6, "proto_type": 1, "correlation_id": "f8e538e4bf535025bfdd8c99080cd2ff", "srcIp": "127.0.0.1", "srcPort": 5060, "dstIp": "52.114.75.24", "dstPort": "9024", "time_sec": 1608374719587, "time_usec": 0 } }

Schermata 2020-12-19 alle 11 51 48 Schermata 2020-12-19 alle 11 51 59 Schermata 2020-12-19 alle 11 52 07
lmangani commented 3 years ago

I unfortunately can't help with the format you keep pasting. We need the original in order to validate the parser.

lmangani commented 3 years ago

@spady7 to be clear. We don't know anything about those logs, we do not have any such SBC and thus we're guessing with you how to parse them. Apparently each syslog event can contain pieces of a SIP message. As you see above, we parse those we understand, while for all other cases you get a failure ie [Sat, 19 Dec 2020 10:45:06 GMT] ERROR failed parsing Incoming SIP which are the ones you should inspect further. I think having the file would help, you can send it to support@sipcapture.org privately if you wish.

spady7 commented 3 years ago

Ok, email sent to support@sipcapture.org

regards

lmangani commented 3 years ago

We need the logs from syslog. not file, or the parsing will be entirely different. Here's the recipe to do so:

input {
  udp {
    host => 0.0.0.0
    port => 514
    type => syslog
  }
}

output {
  stdout {}
  file {
    path => "/tmp/audiocodes.json"
    serializer => "json_logstash"
  }
}

Run the above, perform a full call, and then send us the audiocodes.json file - we'll be able to use it to fix the parser :)

lmangani commented 3 years ago

By the way question for anyone using those logs - if ANY of those events reveals the IP:PORT of the realms used, please suggest so ;)

lmangani commented 3 years ago

@spady7 the latest JSON file seems perfect, will take a look once possible and update you here

lmangani commented 3 years ago

@spady7 please try again with @pastash/filter_app_audiocodes@1.0.15

spady7 commented 3 years ago

Hi, I checked the manuals and here are the only information about how the syslog message is structured. As I told you earlier the whole SIP call is marked with the value "SID". In fact, if I analyze the syslog trace with the tool provided by Audiocodes and I filter the SID value, I get the entire SIP call. Syslog Format.pdf

lmangani commented 3 years ago

We can try use that as the correlation ID but it seems VERY ephemeral and would overlap often. Not good in general. Have you tried the last version? I see some issues with reassembling still but it should produce most messages.

spady7 commented 3 years ago

I sent you audiocodes.json output. Seam to be more outputs but i saw on CLI many error like this:

[Sat, 19 Dec 2020 18:08:14 GMT] ERROR failed parsing Outgoing SIP. Cache on! [Sat, 19 Dec 2020 18:08:14 GMT] ERROR failed parsing Outgoing SIP. Cache on! [Sat, 19 Dec 2020 18:08:14 GMT] ERROR Exception has been catch, it' a bug [Sat, 19 Dec 2020 18:08:14 GMT] ERROR Please submit an issue on https://github.com/sipcapture/pastash [Sat, 19 Dec 2020 18:08:14 GMT] ERROR Exception: TypeError: Cannot read property '1' of null at FilterAppAudiocodes.process (/usr/local/lib/node_modules/@pastash/filter_app_audiocodes/filter_app_audiocodes.js:119:39) at FilterAppAudiocodes. (/usr/local/lib/node_modules/@pastash/pastash/lib/lib/base_filter.js:21:24) at FilterAppAudiocodes.emit (node:events:376:20) at FilterAddVersion. (/usr/local/lib/node_modules/@pastash/pastash/lib/agent.js:260:14) at FilterAddVersion.emit (node:events:376:20) at FilterAddVersion. (/usr/local/lib/node_modules/@pastash/pastash/lib/lib/base_filter.js:27:18) at FilterAddVersion.emit (node:events:376:20) at FilterAddTimestamp. (/usr/local/lib/node_modules/@pastash/pastash/lib/agent.js:260:14) at FilterAddTimestamp.emit (node:events:376:20) at FilterAddTimestamp. (/usr/local/lib/node_modules/@pastash/pastash/lib/lib/base_filter.js:27:18) [Sat, 19 Dec 2020 18:08:14 GMT] ERROR TypeError: Cannot read property '1' of null at FilterAppAudiocodes.process (/usr/local/lib/node_modules/@pastash/filter_app_audiocodes/filter_app_audiocodes.js:119:39) at FilterAppAudiocodes. (/usr/local/lib/node_modules/@pastash/pastash/lib/lib/base_filter.js:21:24) at FilterAppAudiocodes.emit (node:events:376:20) at FilterAddVersion. (/usr/local/lib/node_modules/@pastash/pastash/lib/agent.js:260:14) at FilterAddVersion.emit (node:events:376:20) at FilterAddVersion. (/usr/local/lib/node_modules/@pastash/pastash/lib/lib/base_filter.js:27:18) at FilterAddVersion.emit (node:events:376:20) at FilterAddTimestamp. (/usr/local/lib/node_modules/@pastash/pastash/lib/agent.js:260:14) at FilterAddTimestamp.emit (node:events:376:20) at FilterAddTimestamp. (/usr/local/lib/node_modules/@pastash/pastash/lib/lib/base_filter.js:27:18)

Il giorno sab 19 dic 2020 alle ore 19:07 Lorenzo Mangani < notifications@github.com> ha scritto:

We can try use that as the correlation ID but it seems VERY ephemeral and would overlap often. Not good in general. Have you tried the last version? I see some issues with reassembling still but it should produce most messages.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/sipcapture/paStash/issues/75#issuecomment-748506159, or unsubscribe https://github.com/notifications/unsubscribe-auth/AHRIEAKAHE5PRHVW5Z5SN2DSVTTV3ANCNFSM4U72QSPA .

lmangani commented 3 years ago

Those logs are are as depressing as this format :)

Please try the latest version one more time if you can, let's see if it makes any difference

+ @pastash/filter_app_audiocodes@1.0.16
lmangani commented 3 years ago

NOTE: There's still a nasty issue with reassembling chained logs and parsing timestamps so certain messages WILL be missed.

lmangani commented 3 years ago

@spady7 i think we got it working. Your next test with the latest version should be more interesting ;)

image

lmangani commented 3 years ago

Audiocodes works i bit complicated way. It use 'entities' (like ATA) and to this entity is associated a sip interface and to that sip interface is associated a network interface. This is way ( i suppose) we cannot see directly IP:PORT on syslog. But, we could think to put inside 'pastash_audiocodes.conf' a "MAPPING" of that name to an IP:PORT (I know it because i ve configured on Audiocodes sbc). Does should work? The name of the "trunk" or whatever seems to be inside the parenthesis, ATA in this example below possibly?

Could you provide some examples of this config? I'll prepare some mapping array to hold it.

lmangani commented 3 years ago

@spady7 there's a good chance you will see RTP MOS reports as well :) Curious to hear what your test results will be

spady7 commented 3 years ago

Which version have I to test now? i'am bit confused....;-) ;-) ;-) last one i get is "1.0.16"

Il giorno dom 20 dic 2020 alle ore 16:35 Lorenzo Mangani < notifications@github.com> ha scritto:

@spady7 https://github.com/spady7 there's a good chance you will see RTP MOS reports as well :) Curious to hear what your test results will be

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/sipcapture/paStash/issues/75#issuecomment-748623177, or unsubscribe https://github.com/notifications/unsubscribe-auth/AHRIEANLXLLSZKWDFSPTHNLSVYKV3ANCNFSM4U72QSPA .

spady7 commented 3 years ago

Yes, no problem. I can. but i prefer share you my screen and expose you configuration. I cannot share here.

Il giorno dom 20 dic 2020 alle ore 00:39 Lorenzo Mangani < notifications@github.com> ha scritto:

Audiocodes works i bit complicated way. It use 'entities' (like ATA) and to this entity is associated a sip interface and to that sip interface is associated a network interface. This is way ( i suppose) we cannot see directly IP:PORT on syslog. But, we could think to put inside 'pastash_audiocodes.conf' a "MAPPING" of that name to an IP:PORT (I know it because i ve configured on Audiocodes sbc). Does should work? The name of the "trunk" or whatever seems to be inside the parenthesis, ATA in this example below possibly? … <#m7109771321670206548> ---- Incoming SIP Message from 10.160.21.21:5060 to SIPInterface #3 https://github.com/sipcapture/paStash/pull/3 (ATA) UDP TO(#3 https://github.com/sipcapture/paStash/pull/3) ---- NOTE: The parsing format of the syslog events and the txt are different enough to cause issues so i'm basing this on the syslog format Il giorno ven 18 dic 2020 alle ore 00:20 Agiftel Longwave agiftel@gmail.com ha scritto: Strange. 'ngrep -W byline port 9069 -d any' outputs nothing. port 9069 is my choice, yes. Il giorno ven 18 dic 2020 alle ore 00:12 Lorenzo Mangani < @.***> ha scritto: > Ok next run ngrep -W byline port 9069 -d any to check if any HEP > messages are being sent. I assume the non-standard port for HEP is your > choice, default would be 9060 for HOMER. > > The name of the "trunk" or whatever seems to be inside the parenthesis, > ATA in this example below possibly? > > ---- Incoming SIP Message from 10.160.21.21:5060 to SIPInterface #3 https://github.com/sipcapture/paStash/pull/3 (ATA) UDP TO(#3 https://github.com/sipcapture/paStash/pull/3) ---- > > NOTE: The parsing format of the syslog events and the txt are different > enough to cause issues so i'm basing this on the syslog format > > — > You are receiving this because you were mentioned. > Reply to this email directly, view it on GitHub > <#75 (comment) https://github.com/sipcapture/paStash/issues/75#issuecomment-747761718>,

or unsubscribe > https://github.com/notifications/unsubscribe-auth/AHRIEAKVNPVTNJVMDUALFPLSVKF57ANCNFSM4U72QSPA . >

Could you provide some examples of this config? I'll prepare some mapping array to hold it.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/sipcapture/paStash/issues/75#issuecomment-748540129, or unsubscribe https://github.com/notifications/unsubscribe-auth/AHRIEAPUI5KQHX2CKYUJ35TSVU2R5ANCNFSM4U72QSPA .

spady7 commented 3 years ago

Ok, sorry. I saw it. Is "1.0.23" Let me test...

Il giorno dom 20 dic 2020 alle ore 18:28 Agiftel Longwave agiftel@gmail.com ha scritto:

Yes, no problem. I can. but i prefer share you my screen and expose you configuration. I cannot share here.

Il giorno dom 20 dic 2020 alle ore 00:39 Lorenzo Mangani < notifications@github.com> ha scritto:

Audiocodes works i bit complicated way. It use 'entities' (like ATA) and to this entity is associated a sip interface and to that sip interface is associated a network interface. This is way ( i suppose) we cannot see directly IP:PORT on syslog. But, we could think to put inside 'pastashaudiocodes.conf' a "MAPPING" of that name to an IP:PORT (I know it because i ve configured on Audiocodes sbc). Does should work? The name of the "trunk" or whatever seems to be inside the parenthesis, ATA in this example below possibly? … <#m-7817995491383188603_m7109771321670206548> ---- Incoming SIP Message from 10.160.21.21:5060 to SIPInterface #3 https://github.com/sipcapture/paStash/pull/3 (ATA) UDP TO(#3 https://github.com/sipcapture/paStash/pull/3) ---- NOTE: The parsing format of the syslog events and the txt are different enough to cause issues so i'm basing this on the syslog format Il giorno ven 18 dic 2020 alle ore 00:20 Agiftel Longwave agiftel@gmail.com ha scritto: Strange. 'ngrep -W byline port 9069 -d any' outputs nothing. port 9069 is my choice, yes. Il giorno ven 18 dic 2020 alle ore 00:12 Lorenzo Mangani < @.***> ha scritto: > Ok next run ngrep -W byline port 9069 -d any to check if any HEP > messages are being sent. I assume the non-standard port for HEP is your > choice, default would be 9060 for HOMER. > > The name of the "trunk" or whatever seems to be inside the parenthesis, > ATA in this example below possibly? > > ---- Incoming SIP Message from 10.160.21.21:5060 to SIPInterface #3 https://github.com/sipcapture/paStash/pull/3 (ATA) UDP TO(#3 https://github.com/sipcapture/paStash/pull/3) ---- > > NOTE: The parsing format of the syslog events and the txt are different > enough to cause issues so i'm basing this on the syslog format > > — > You are receiving this because you were mentioned. > Reply to this email directly, view it on GitHub > <#75 (comment) https://github.com/sipcapture/paStash/issues/75#issuecomment-747761718>,

or unsubscribe > https://github.com/notifications/unsubscribe-auth/AHRIEAKVNPVTNJVMDUALFPLSVKF57ANCNFSM4U72QSPA . >

Could you provide some examples of this config? I'll prepare some mapping array to hold it.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/sipcapture/paStash/issues/75#issuecomment-748540129, or unsubscribe https://github.com/notifications/unsubscribe-auth/AHRIEAPUI5KQHX2CKYUJ35TSVU2R5ANCNFSM4U72QSPA .

lmangani commented 3 years ago

Yeah, just always pull the latest available, they get pushed as bugs get fixed. By default it will only try reassemble SIP out, I've added a few options documented here: https://github.com/sipcapture/paStash/blob/next/plugins/filters/app_audiocodes/app_audiocodes.md

lmangani commented 3 years ago

Try using this config for IP autodetection (very sketchy logs for TLS, only you can tell if it works)

filter {
  app_audiocodes {
    autolocal => true
    qos => true
  }
}
lmangani commented 3 years ago

All seems to work! If there are other Audiocodes lurkers watching this thread and willing to try, crawl out, we'll help :)

lmangani commented 3 years ago

Documented here: https://github.com/sipcapture/paStash/wiki/Example:-AUDIOCODES-Syslog

Good luck @spady7! In case of issues or new discoveries, please open a new issue for clean tracking!