SDP issues and etc with Audiocodes filter

os11k commented 3 years ago

I would like to open this issue to discuss some known bugs/problems.

1) @spady7 could you please share with me logs, so I can recheck why SDP for you is not getting parsed. I will need logs for such kind of INVITE? I'm interested in one line what starts with reassembled line and has that INVITE what you see in homer without SDP, or you can share full file. If you want you can try to fix it by yourself, I think if you will update filter_app_audiocodes.js line 119 to following:

regex = /(.*)---- Incoming SIP Message from (.*) to SIPInterface #[0-99] \((.*)\) (.*) TO.*--- #012(.*)(.*)/g;

And line 156 to following:

regex = /(.*)---- Outgoing SIP Message to (.*) from SIPInterface #[0-99] \((.*)\) (.*) TO.*--- #012(.*)(.*)/g;

It will do the trick, not sure how this is correct. :) Maybe @lmangani will be against it.

Basically old regex saves to 5th group everything before #012 #012, but SDP are exactly after #012 #012

2) I'm trying to use in pastash filter clone from logstash, so something like this I tried:

input {
  udp {
    host => 0.0.0.0
    port => 10514
    type => syslog
    tags => ["10514"]
  }
  udp {
    host => 0.0.0.0
    port => 10515
    type => syslog
    tags => ["10515"]
  }
}

filter {
clone {
    add_tag => [ "copy" ]
  }
  if "10514" in [tags] {
  app_audiocodes {
    debug => true
    autolocal => true
    qos => true
    localip => 10.43.56.13
  }
  }
  if "10515" in [tags] {
  app_audiocodes {
    debug => true
    autolocal => true
    qos => true
    localip => 10.43.156.157
  }
  }
}

output {
  if "copy" not in [tags] {
    if [rcinfo] != 'undefined' {
        hep {
          host => '10.10.151.163'
          port => 9060
          hep_id => 100
          hep_type => 1
        }
    }
  } else {
    stdout {}
 }
}

Idea behind this is to send everything to Homer and to save all logs unchanged additionally somewhere so we can dig those logs if something get lost, because this is still quite experimental. I plan to save this to graylog, so sending out to syslog/graylog will be ideal, nevertheless stdout will work too, because I run pastash in docker and I can use docker driver for sending out logs to graylog. @lmangani do you know why clone do not works? Any betters ideas how to mirror completely everything to graylog?

3) Sometimes I see in Homer IP 10.2.0.4, but not one what I configured with localip. Here some logs:

DEBUG <133>[S=432471] [SID=4bc9e3:2:11204]  SIP/2.0 404 Not Found
FROM: +123456<sip:+123456@myapp.app>;tag=1c352922656
TO: <sip:+98765@stams1.myappapp.net>
CSEQ: 1 INVITE
CALL-ID: 11335363372112021154723@stams1.myappapp.net
VIA: SIP/2.0/TLS stams1.myappapp.net:5061;branch=z9hG4bKac871490062
REASON: Q.850;cause=1;text="cf264671-c7af-43cc-acc4-579a0589fe10;RNL"
CONTENT-LENGTH: 0
ALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY
SERVER: Microsoft.PSTNHub.SIPProxy v.2021.1.15.7 i.USEA.1

 [Time:21-01@15:47:23.269]
reassembled line <133>[S=432470] [SID=4bc9e3:2:11204]  (N   361291) ---- Incoming SIP Message from 52.114.132.46:5061 to SIPInterface #0 (SIPInterface_0) TLS TO(#2005) SocketID(1) ----  SIP/2.0 404 Not Found #012FROM: +123456<sip:+123456@myapp.app>;tag=1c352922656 #012TO: <sip:+98765@stams1.myappapp.net> #012CSEQ: 1 INVITE #012CALL-ID: 11335363372112021154723@stams1.myappapp.net #012VIA: SIP/2.0/TLS stams1.myappapp.net:5061;branch=z9hG4bKac871490062 #012REASON: Q.850;cause=1;text="cf264671-c7af-43cc-acc4-579a0589fe10;RNL" #012CONTENT-LENGTH: 0 #012ALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY #012SERVER: Microsoft.PSTNHub.SIPProxy v.2021.1.15.7 i.USEA.1 #012 #012
[Thu, 21 Jan 2021 15:47:22 GMT] ERROR SESSION SID 11204
[STDOUT] {
  "payload": "SIP/2.0 404 Not Found \r\nFROM: +123456<sip:+123456@myapp.app>;tag=1c352922656 \r\nTO: <sip:+98765@stams1.myappapp.net> \r\nCSEQ: 1 INVITE \r\nCALL-ID: 11335363372112021154723@stams1.myappapp.net \r\nVIA: SIP/2.0/TLS stams1.myappapp.net:5061;branch=z9hG4bKac871490062 \r\nREASON: Q.850;cause=1;text=\"cf264671-c7af-43cc-acc4-579a0589fe10;RNL\" \r\nCONTENT-LENGTH: 0 \r\nALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY \r\nSERVER: Microsoft.PSTNHub.SIPProxy v.2021.1.15.7 i.USEA.1\r\n\r\n",
  "rcinfo": {
    "type": "HEP",
    "version": 3,
    "payload_type": "SIP",
    "ip_family": 2,
    "protocol": 6,
    "proto_type": 1,
    "correlation_id": "11335363372112021154723@stams1.myappapp.net",
    "srcIp": "52.114.132.46",
    "srcPort": "5061",
    "dstIp": "10.2.0.4",
    "dstPort": "5061",
    "time_sec": 1611244042,
    "time_usec": 696,
    "captureId": "100",
    "capturePass": "MyHep"
  }
}
DEBUG <133>[S=432473] [SID=4bc9e3:2:11204]  (N   361293) ---- Outgoing SIP Message to 52.114.132.46:5061 from SIPInterface #0 (SIPInterface_0) TLS TO(#2005) SocketID(1) ---- [Time:21-01@15:47:23.269]
[Thu, 21 Jan 2021 15:47:22 GMT] ERROR SESSION SID 11204
[Thu, 21 Jan 2021 15:47:22 GMT] ERROR failed parsing Outgoing SIP. Cache on!
DEBUG <133>[S=432472] [SID=4bc9e3:2:11204]  (N   361292) AcSIPCall(#2987): Handling 404 in state Proceeding [Time:21-01@15:47:23.269]
reassembled line <133>[S=432473] [SID=4bc9e3:2:11204]  (N   361293) ---- Outgoing SIP Message to 52.114.132.46:5061 from SIPInterface #0 (SIPInterface_0) TLS TO(#2005) SocketID(1) ----  (N   361292) AcSIPCall(#2987): Handling 404 in state Proceeding
[Thu, 21 Jan 2021 15:47:22 GMT] ERROR SESSION SID 11204
[STDOUT] {
  "payload": "(N   361292) AcSIPCall(#2987): Handling 404 in state Proceeding\r\n\r\n",
  "rcinfo": {
    "type": "HEP",
    "version": 3,
    "payload_type": "SIP",
    "ip_family": 2,
    "protocol": 17,
    "proto_type": 1,
    "correlation_id": "11204",
    "srcIp": "10.2.0.4",
    "srcPort": "5061",
    "dstIp": "52.114.132.46",
    "dstPort": "5061",
    "time_sec": 1611244042,
    "time_usec": 697,
    "captureId": "100",
    "capturePass": "MyHep"
  }
}
DEBUG <133>[S=432474] [SID=4bc9e3:2:11204]  ACK sip:+98765@stams1.myappapp.net SIP/2.0
Via: SIP/2.0/TLS stams1.myappapp.net:5061;alias;branch=z9hG4bKac871490062
Max-Forwards: 70
From: 123456 <sip:123456@myapp.app>;tag=1c352922656
To: <sip:+98765@stams1.myappapp.net>
Call-ID: 11335363372112021154723@stams1.myappapp.net
CSeq: 1 ACK
Contact: <sip:stams1.myappapp.net:5061;transport=tls>
User-Agent: Mediant SW/v.7.20A.258.271
Content-Length: 0

 [Time:21-01@15:47:23.269]
[Thu, 21 Jan 2021 15:47:22 GMT] ERROR SESSION SID 11204

4) Sometimes I see this "Java error logs" and this do not seems right:

reassembled line <133>[S=1858983] [SID=8999b9:10:48575]  (N  1549767) ---- Incoming SIP Message from 52.114.132.46:6152 to SIPInterface #0 (SIPInterface_0) TLS TO(#1954) SocketID(52) ----  (N  1549766) (#404)Route found (0), Route by Address, IP Group 2 -> 1 (Teams -> myapp), Url:internal:0;
[Thu, 21 Jan 2021 15:47:44 GMT] ERROR SESSION SID 48575
[Thu, 21 Jan 2021 15:47:44 GMT] ERROR Conditional error Error: In / not in right args must be an array : undefined
    at Object.exports.compute (/usr/local/lib/node_modules/@pastash/pastash/lib/lib/condition_evaluator.js:89:13)
    at FilterAppAudiocodes.BaseComponent.processMessage (/usr/local/lib/node_modules/@pastash/pastash/lib/lib/base_component.js:260:33)
    at FilterAppAudiocodes.<anonymous> (/usr/local/lib/node_modules/@pastash/pastash/lib/lib/base_filter.js:20:16)
    at FilterAppAudiocodes.emit (events.js:198:13)
    at FilterAppAudiocodes.<anonymous> (/usr/local/lib/node_modules/@pastash/pastash/lib/agent.js:260:14)
    at FilterAppAudiocodes.emit (events.js:198:13)
    at FilterAppAudiocodes.<anonymous> (/usr/local/lib/node_modules/@pastash/pastash/lib/lib/base_filter.js:27:18)
    at FilterAppAudiocodes.emit (events.js:198:13)
    at FilterAddVersion.<anonymous> (/usr/local/lib/node_modules/@pastash/pastash/lib/agent.js:260:14)
    at FilterAddVersion.emit (events.js:198:13)

lmangani commented 3 years ago

@os11k

regex patch I fully agree here, as long as it works! feel free to submit a PR and we'll test and merge it.
```
Basically old regex saves to 5th group everything before #012 #012, but SDP are exactly after #012 #012
```
clone because of the single threaded nature of pastash this method would bottleneck quickly, the best way with pastash design is to leverage multithreading by running multiple pastash instances handling parallel pipelines. So a main pastash instance will be decoding syslog and dispatching to two others, one for each insert type, doing their own thing independently - in your case using the elastic output or whatnot.

os11k commented 3 years ago

Hi @lmangani ! I discovered quite a big problem. So if we look only on SIP traffic, then before to send HEP packet paStash waits first for ---- Incoming SIP Message or ---- Outgoing SIP Message and then next packet what arrives after it. Then we glue this into one packet, parse it and send out to Homer, if I understood logic correctly. Issue here is that with UDP and in my environment this packets do not arrive in a row and I doubt that they will, in busy system. I personally experienced a problem when for example ---- Incoming SIP Message arrives and then there are some more messages arrives and only then arrives second part what we expect, nevertheless this is not such a huge issue, because I can check what sequence number second packet has and if it is not +1 then I do not glue it, so this is fixable. And this even might work a bit. A bigger problem is when second part packet arrives before ---- Incoming SIP Message and then we can't do much or when there are several packets are mixed in between. In my system what do not have any calls at all only when I do test paStash I experienced all of this cases. In theory I hope that there will be not much packets lost in not a busy system, but if we take a system what has a lot of load, then I think this will become a problem. What do you think @lmangani ? Do you think there is any possibility to fix it? I think that only one solution will be to parse only actual SIP message, but then we do not have information about sender, in my system it might be not a big problem, I do not have a lot of trunks and I can kind of hardcode source and destination.

lmangani commented 3 years ago

We should have a max counter for the merging operation and reset it when it exceeds. ie: max 2 iterations before resetting cache.

lmangani commented 3 years ago

Of course, If you control your switch/traffic, just mirror it to heplify and you do not need this unless its TLS

Wolffis commented 3 years ago

Just to comment that I updated the Audiocodes SBC from old 7.20A.202. version to 7.20A.258.367 (latest LTS) and paStash to

@pastash/pastash@1.0.71
@pastash/filter_app_audiocodes@1.0.25

The syslog format seemed to change somewhat and now I can see the traffic at least in the Homer.

I had to put in 'localip' config to change the IP from paStash host IP to correct SBC IP. Also only the interface used to send syslog traffic is identified and not the external SIP IP for example:

Proxy(10.10.10.1) -> Audiocodes-internal(10.10.10.2) -> External-host(1.2.3.4)

Should be: Proxy(10.10.10.1) -> Audiocodes-internal(10.10.10.2) -> Audiocodes-external(4.3.2.1) -> External-host(1.2.3.4)

This might be something I can configure better? SDP is visible, but I still get "ERROR failed parsing Incoming SIP. Cache on!" with some SIP messages and I think they are not visible either in the Homer.

But anyway, looks great and amazing software as always, thanks guys!

os11k commented 3 years ago

We should have a max counter for the merging operation and reset it when it exceeds. ie: max 2 iterations before resetting cache.

Hi @lmangani ! Could you please explain what you meant here?

os11k commented 3 years ago

Hi @lmangani ! I just created new PR, purpose of that PR is to make sure that we glue correct packet towards one what is in cache.

os11k commented 3 years ago

Thank you for merging my PR @lmangani ! Now in my plans is to test this on production and see how much packets will be messed up when there will be some traffic, I hope this will not be a big problem, but you never knows. Based on that tests I will think what to do next.

I'm thinking about your proposal regarding maximum attempts for merging packets. Not sure that we need that, at least on this point.

lmangani commented 3 years ago

@pastash/filter_app_audiocodes@1.0.26

lmangani commented 3 years ago

@os11k thanks for being an awesome open-source citizen!

os11k commented 3 years ago

Hi @Wolffis ! Regarding:

Proxy(10.10.10.1) -> Audiocodes-internal(10.10.10.2) -> External-host(1.2.3.4)

Should be: Proxy(10.10.10.1) -> Audiocodes-internal(10.10.10.2) -> Audiocodes-external(4.3.2.1) -> External-host(1.2.3.4)

This will need some code changes and I doubt I can do this now, this is definitely not in my bucket list so far, but if I will have nothing to do I might fix this at some point in future.

ERROR failed parsing Incoming SIP. Cache on!

This error is expected, so when Audiocodes sends packet to syslog it actually sends 2 packets for 1 SIP message. First packet is containing information regarding who send whom packet and when paStash is parsing this packet you see this error. Next packet from Audiocodes contains actual SIP packet.

os11k commented 3 years ago

I'm thinking now to create some kind of array for 5 messages(or more) and cash those 5 messages, so in this case if 5 messages will arrive in mix we can properly glue them. Still I can't find simple solution when 2nd part arrive before 1st, but maybe we do not need it. What do you think @lmangani ?

lmangani commented 3 years ago

I solved the same problem in other pastash applications using an LRU.

Basically a bulking cache with ttl where we can store pieces/fragments over short periods, emitting everything out at intervals reassembling any fragments in the process using any common grouping identifier, and on to the next dump. I can find you some examples in pastash apps later or implement something this weekend.

os11k commented 3 years ago

Hi @lmangani ! can you please share some examples regarding LRU? I will try to work on this on weekends. Thank you!

lmangani commented 2 years ago

@os11k no longer using this?

os11k commented 2 years ago

Hi @lmangani , I just have a feeling that you are developing a better version of Pastash to work with audiocodes particularly. :)

lmangani commented 2 years ago

Indeed I'm working on a plugin that uses the extended logging format option to avoid the many issues the fragmented one has

spady7 commented 11 months ago

@lmangani audiocodes plugin had been compleated? Where can i find it? i never see it listed on pastash's filters.

sipcapture / paStash

SDP issues and etc with Audiocodes filter #80