Unable to see paStash messages (AudioCodes plugin) in Homer 10

[myrcinos]

Hi,

This is my second try with the following setup AudioCodes via Syslog to paStash -> Homer 10 (last time I tried with Homer 7). I installed a fresh Debian 12 VM with Docker and Homer 10 inside a container. I used docker compose as recommended. Homer and Grafana work fine, I can see test HEP messages from hepgen in Homer. Then I installed the AudioCodes filter plugin. It was installed in the global folder location:

myrcin@Homer:~$ npm list -g --depth 0
/usr/local/lib
├── @pastash/filter_app_audiocodes@1.2.0
├── @pastash/pastash@1.0.82
└── hepgen.js@1.0.9

I use basic config file copied from Github:

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

filter {
  app_audiocodes{}
}

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

When I start paStash it seems to be fine. If I turn on Debug log level it complains about the missing plugin but it was already discussed in another issue and can be safely ignored.

myrcin@Homer:~$ sudo pastash --config_file=/home/myrcin/audiocodes.conf
[Wed, 11 Dec 2024 14:37:03 GMT] NOTICE Starting pastash 1.0.82
[Wed, 11 Dec 2024 14:37:03 GMT] INFO Max http socket 100
[Wed, 11 Dec 2024 14:37:03 GMT] INFO Loading config file : /home/myrcin/audiocodes.conf
[Wed, 11 Dec 2024 14:37:03 GMT] INFO File loaded, 3 urls found
[Wed, 11 Dec 2024 14:37:03 GMT] INFO Loading config : 6 urls
[Wed, 11 Dec 2024 14:37:03 GMT] INFO Initializing output HEP/EEP Server
[Wed, 11 Dec 2024 14:37:03 GMT] INFO Start output to HEP udp to 127.0.0.1:9060
[Wed, 11 Dec 2024 14:37:03 GMT] INFO Initializing filter AddHost
[Wed, 11 Dec 2024 14:37:03 GMT] INFO Initializing filter AddTimestamp
[Wed, 11 Dec 2024 14:37:03 GMT] INFO Initializing filter AddVersion
Loading npm module... @pastash/filter_app_audiocodes
[Wed, 11 Dec 2024 14:37:03 GMT] INFO Initializing filter AppAudiocodes
[Wed, 11 Dec 2024 14:37:03 GMT] INFO Initialized App Audiocodes SysLog to SIP/HEP parser
[Wed, 11 Dec 2024 14:37:03 GMT] INFO Initializing input Udp
[Wed, 11 Dec 2024 14:37:03 GMT] INFO Start listening on udp 0.0.0.0:514
[Wed, 11 Dec 2024 14:37:03 GMT] INFO Config loaded.

When I make a test call, I get the following output in the console:

[Wed, 11 Dec 2024 14:38:34 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     5204) ---- Incoming SIP Message from 192.168.3.115:47097 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Wed, 11 Dec 2024 14:38:34 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     5205) ---- Outgoing SIP Message to 192.168.3.115:47097 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Wed, 11 Dec 2024 14:38:34 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     5207) ---- Incoming SIP Message from 192.168.3.115:47097 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Wed, 11 Dec 2024 14:38:34 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     5208) ---- Incoming SIP Message from 192.168.3.115:47097 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Wed, 11 Dec 2024 14:38:34 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     5209) ---- Outgoing SIP Message to 192.168.3.115:47097 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Wed, 11 Dec 2024 14:38:35 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     5210) ---- Incoming SIP Message from 192.168.3.115:47097 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Wed, 11 Dec 2024 14:38:35 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     5211) ---- Outgoing SIP Message to 192.168.3.115:47097 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Wed, 11 Dec 2024 14:38:35 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     5213) ---- Outgoing SIP Message to 192.168.3.115:47097 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Wed, 11 Dec 2024 14:38:35 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     5214) ---- Incoming SIP Message from 192.168.3.115:47097 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Wed, 11 Dec 2024 14:38:35 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     5215) ---- Outgoing SIP Message to 192.168.3.115:47097 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Wed, 11 Dec 2024 14:38:36 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     5216) ---- Incoming SIP Message from 192.168.3.115:47097 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Wed, 11 Dec 2024 14:38:36 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     5217) ---- Outgoing SIP Message to 192.168.3.115:47097 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----

tcpdump shows that SYSLOG messages are being received on port UDP 514 from AudioCodes. However, if I run tcpdump withing the heplify-server container there is nothing on the destination port 9060:

~ # tcpdump -nn dst port 9060
tcpdump: verbose output suppressed, use -v[v]... for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), snapshot length 262144 bytes

The AudioCodes firmware version is:

7.40A.500.781

What am I doing wrong? Could you please help me troubleshoot this issue? I am happy to provide more details. Thank you.

[myrcinos]

Today I found that one REGISTER message was recorded in Homer. Just one and subsequent REGISTERES were no longer recorded.

[Dletta]

@myrcinos Could you add a stdout {} to your output {} and check if you see any messages before the hep output?

The log you see indicates that app_audiocodes was unable to find a 'complete' SIP message to send onward and process.

[myrcinos]

@Dletta This is now my config file:

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

filter {
  app_audiocodes{
    debug => false
    #autolocal => true
    ini => '/home/myrcin/audiocodeslocal.ini'
  }
}

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

Here is what I got in the console:

myrcin@Homer:~$ sudo pastash --config_file=/home/myrcin/audiocodes.conf
[Fri, 13 Dec 2024 12:32:08 GMT] NOTICE Starting pastash 1.0.82
[Fri, 13 Dec 2024 12:32:08 GMT] INFO Max http socket 100
[Fri, 13 Dec 2024 12:32:08 GMT] INFO Loading config file : /home/myrcin/audiocodes.conf
[Fri, 13 Dec 2024 12:32:08 GMT] INFO File loaded, 4 urls found
[Fri, 13 Dec 2024 12:32:08 GMT] INFO Loading config : 7 urls
[Fri, 13 Dec 2024 12:32:08 GMT] INFO Initializing output Stdout
[Fri, 13 Dec 2024 12:32:08 GMT] INFO Initializing output HEP/EEP Server
[Fri, 13 Dec 2024 12:32:08 GMT] INFO Start output to HEP udp to 127.0.0.1:9060
[Fri, 13 Dec 2024 12:32:08 GMT] INFO Initializing filter AddHost
[Fri, 13 Dec 2024 12:32:08 GMT] INFO Initializing filter AddTimestamp
[Fri, 13 Dec 2024 12:32:08 GMT] INFO Initializing filter AddVersion
Loading npm module... @pastash/filter_app_audiocodes
[Fri, 13 Dec 2024 12:32:08 GMT] INFO Initializing filter AppAudiocodes
[Fri, 13 Dec 2024 12:32:08 GMT] INFO Initialized App Audiocodes SysLog to SIP/HEP parser
[Fri, 13 Dec 2024 12:32:08 GMT] INFO Marcin Marcin Marcin
[Fri, 13 Dec 2024 12:32:08 GMT] INFO Reading INI file to resolver... /home/myrcin/audiocodeslocal.ini
[Fri, 13 Dec 2024 12:32:08 GMT] INFO INI Loaded undefined Interfaces
[Fri, 13 Dec 2024 12:32:08 GMT] INFO INI Loaded undefined SIP Profiles
[Fri, 13 Dec 2024 12:32:08 GMT] INFO Initializing input Udp
[Fri, 13 Dec 2024 12:32:08 GMT] INFO Start listening on udp 0.0.0.0:514
[Fri, 13 Dec 2024 12:32:08 GMT] INFO Config loaded.
[Fri, 13 Dec 2024 12:32:11 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=862] [BID=665997:5]  FileDescriptorsAudit() number of TPApp open file descriptors 95 LeakCounter 1 (Limit=1038336 TPApp-PID=2619)
[Fri, 13 Dec 2024 12:32:22 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N      927) ---- Incoming SIP Message from 192.168.3.115:48083 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:22 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N      943) ---- Outgoing SIP Message to 192.168.3.115:48083 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:22 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N      956) ---- Incoming SIP Message from 192.168.3.115:48083 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:22 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N      976) ---- Outgoing SIP Message to 192.168.3.115:48083 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:22 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N      977) ---- Incoming SIP Message from 192.168.3.115:48083 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:22 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N      990) ---- Outgoing SIP Message to 192.168.3.115:48083 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:22 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=953] [BID=665997:5]  (N     1001) SIPListeningSocketTCP(#0) Socket debug message: CTcpSocket::HandleSocketEvent socket connectedSocketName: SIPLISTENING#0, FileDesc: 64 
[Fri, 13 Dec 2024 12:32:22 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=954] [BID=665997:5]  (N     1002) SIPListeningSocketTCP(#0) Socket debug message: CTcpServerSocket::IsSocketPending socket is pending for acceptSocketName: SIPLISTENING#0, FileDesc: 64 
[Fri, 13 Dec 2024 12:32:22 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=955] [BID=665997:5]  (N     1003) New SIPSocketReliable created - (#3018) - SocketID=5
[Fri, 13 Dec 2024 12:32:22 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=956] [BID=665997:5]  (N     1004) New TcpSocketAPI created (#3018) - SocketID=5
[Fri, 13 Dec 2024 12:32:22 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=957] [BID=665997:5]  (N     1005) New Socket buffer allocated - (#3019)
[Fri, 13 Dec 2024 12:32:22 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=958] [BID=665997:5]  (N     1006) WhiteListManager: Adding TCPTLSSocket Remote IP: 192.168.3.115, Port: 56659, Interface ID: 0, Local Port: 5060, Protocol: 6 succeeded
[Fri, 13 Dec 2024 12:32:22 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=959] [BID=665997:5]  (N     1007) SIPListeningSocketTCP(#0)::AcceptNewConnection - Incoming connection from 192.168.3.115:56659 accepted. SocketID=5
[Fri, 13 Dec 2024 12:32:22 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1008) ---- Incoming SIP Message from 192.168.3.115:48083 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:22 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1020) ---- Outgoing SIP Message to 192.168.3.115:48083 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:22 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=977] [BID=665997:5]  (N     1023) SIPSocketReliable(#3018)::RetrieveAndHandleMessages - 199 bytes were left in socket:
[Fri, 13 Dec 2024 12:32:22 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=978] [BID=665997:5]  
[Fri, 13 Dec 2024 12:32:22 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1036) ---- Incoming SIP Message from 192.168.3.115:48083 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:22 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1056) ---- Outgoing SIP Message to 192.168.3.115:48083 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:22 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1072) ---- Outgoing SIP Message to 192.168.3.114:6062 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:22 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1073) ---- Incoming SIP Message from 192.168.3.114:6062 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:22 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1077) ---- Incoming SIP Message from 192.168.3.114:6062 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:22 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1088) ---- Outgoing SIP Message to 192.168.3.115:48083 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:29 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1091) ---- Incoming SIP Message from 192.168.3.114:6062 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:29 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1142) ---- Outgoing SIP Message to 192.168.3.115:48083 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:30 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1161) ---- Incoming SIP Message from 192.168.3.115:48083 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:30 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1177) ---- Outgoing SIP Message to 192.168.3.115:48083 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:30 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1178) ---- Incoming SIP Message from 192.168.3.115:48083 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:30 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1191) ---- Outgoing SIP Message to 192.168.3.115:48083 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:30 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1204) ---- Incoming SIP Message from 192.168.3.114:6062 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:31 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1207) ---- Incoming SIP Message from 192.168.3.114:6062 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:33 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1210) ---- Incoming SIP Message from 192.168.3.114:6062 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:33 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1211) ---- Incoming SIP Message from 192.168.3.114:6062 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:33 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1218) ---- Outgoing SIP Message to 192.168.3.115:48083 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:33 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1220) ---- Incoming SIP Message from 192.168.3.115:48083 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:33 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1235) ---- Outgoing SIP Message to 192.168.3.114:6062 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:33 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=1] |MediaReportType|SIPCallId                                                        |SessionId               |Cid  |MediaType |Coder          |Intrv|LocalRtpIp          |LocalRtpPort   |RemoteRtpIp         |RemoteRtpPort|InPackets |OutPackets|LocalPackLoss|RemotePackLoss|RTPdelay |RTPjitter|TxRTPssrc     |RxRTPssrc     |LocalRFactor|RemoteRFactor|LocalMosCQ|RemoteMosCQ|TxRTPIPDiffServ|LatchedRtpIp        |LatchedRtpPort |LatchedT38Ip        |LatchedT38Port |CoderTranscoding |LegId
[Fri, 13 Dec 2024 12:32:33 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=2] |MEDIA_END       |xA7dsSPlV5DLuU6Gl5kG6w..                                        |665997:5:15             |10   |AUDIO     |g711Alaw64k    |20   |192.168.3.250       |6000           |93.177.90.248       |8002         |190       |0         |0            |0             |0        |93       |3075885403    |3970803796    |127         |127          |127       |127        |46             |                    |0              |                    |0              |NO_TRANSCODING   |1
[Fri, 13 Dec 2024 12:32:33 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=3] |SBCReportType   |EPTyp     |SIPCallId                                                       |SessionId               |Orig |SourceIp            |SourcePort   |DestIp              |DestPort   |TransportType   |SrcURI                                   |SrcURIBeforeMap                          |DstURI                                   |DstURIBeforeMap                          |Duration|TrmSd|TrmReason                               |TrmReasonCategory|SetupTime                          |ConnectTime                        |ReleaseTime                        |RedirectReason |RedirectURINum                           |RedirectURINumBeforeMap                  |TxSigIPDiffServ|IPGroup (name)                  |SrdId (name)                    |SIPInterfaceId (name)           |ProxySetId (name)               |IpProfileId (name)              |MediaRealmId (name)             |DirectMedia|SIPTrmReason|SIPTermDesc                   |Caller                                             |Callee                               |Trigger |LegId|VoiceAIConnectorName
[Fri, 13 Dec 2024 12:32:33 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=4] |CALL_END        |SBC       |xA7dsSPlV5DLuU6Gl5kG6w..                                        |665997:5:15             |RMT  |192.168.3.115       |48083        |192.168.3.250       |5060       |UDP             |+48605555483@192.168.3.250               |+48605555483@192.168.3.250               |+48605555484@192.168.3.250               |+48605555484@192.168.3.250               |0       |LCL  |GWAPP_NORMAL_CALL_CLEAR                 |NO_ANSWER        |12:32:19.384  UTC Fri Dec 13 2024  |                                   |12:32:31.079  UTC Fri Dec 13 2024  |-1             |                                         |                                         |24             |Users                           |DefaultSRD                      |SIPInterface_0                  |                                |                                |DefaultRealm                    |no         |BYE         |                              |+48605555483                                       |                                     |Normal  |1    |
[Fri, 13 Dec 2024 12:32:33 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=5] |MEDIA_END       |201258299913122024123219@192.168.3.250                          |665997:5:15             |11   |AUDIO     |g711Alaw64k    |20   |192.168.3.250       |6004           |192.168.3.114       |6008         |0         |189       |0            |0             |0        |4294967295|565297211     |4294967295    |127         |127          |127       |127        |46             |                    |0              |                    |0              |NO_TRANSCODING   |2
[Fri, 13 Dec 2024 12:32:33 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=6] |CALL_END        |SBC       |201258299913122024123219@192.168.3.250                          |665997:5:15             |LCL  |192.168.3.250       |5060         |192.168.3.114       |6062       |UDP             |+48605555483@192.168.3.250               |+48605555483@192.168.3.250               |+48605555484@192.168.3.250               |+48605555484@192.168.3.250               |0       |RMT  |GWAPP_NORMAL_CALL_CLEAR                 |NO_ANSWER        |12:32:19.384  UTC Fri Dec 13 2024  |                                   |12:32:31.079  UTC Fri Dec 13 2024  |-1             |                                         |                                         |24             |Users                           |DefaultSRD                      |SIPInterface_0                  |                                |                                |DefaultRealm                    |no         |BYE         |                              |+48605555483                                       |                                     |Normal  |2    |
[Fri, 13 Dec 2024 12:32:34 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1279) ---- Incoming SIP Message from 192.168.3.115:48083 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:34 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1295) ---- Outgoing SIP Message to 192.168.3.115:48083 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:34 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1296) ---- Incoming SIP Message from 192.168.3.115:48083 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:34 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1309) ---- Outgoing SIP Message to 192.168.3.115:48083 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:37 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     1325) ---- Incoming SIP Message from 192.168.3.114:6062 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
[Fri, 13 Dec 2024 12:32:52 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=1318] [BID=665997:5]  (N     1339) SIPSocketReliable(#3018)::DispatchQueueEvent(MESSAGE_ARRIVAL_TIMER_EXPIRED) - Closing connection
[Fri, 13 Dec 2024 12:32:52 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=1319] [BID=665997:5]  (N     1340) TcpSocketAPI(#3018) Removing closed socket from White List
[Fri, 13 Dec 2024 12:32:52 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=1320] [BID=665997:5]  (N     1341) WhiteListManager: Removing TCPTLSSocket Remote IP: 192.168.3.115, Port: 56659, Interface ID: 0, Local Port: 5060, Protocol: 6 succeeded
[Fri, 13 Dec 2024 12:32:52 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=1321] [BID=665997:5]  (N     1342) SIPSocketReliable(#3018)::ReleaseConnection - Closing connection
[Fri, 13 Dec 2024 12:32:52 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=1322] [BID=665997:5]  (N     1343) TcpSocketAPI(#3018) Released
[Fri, 13 Dec 2024 12:32:52 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=1323] [BID=665997:5]  (N     1344) SIPSocketReliable(#3018) Released - SocketID=5
[Fri, 13 Dec 2024 12:32:52 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=1324] [BID=665997:5]  (N     1345) TcpSocketAPI(#3018)::ReleaseCSocket - Closing socket
[Fri, 13 Dec 2024 12:32:52 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=1325] [BID=665997:5]  (N     1346) Socket buffer released - (#3019)
[Fri, 13 Dec 2024 12:33:11 GMT] ERROR Invalid SIP Message, missing SID or SEQ in Line: [S=1326] [BID=665997:5]  FileDescriptorsAudit() number of TPApp open file descriptors 96 LeakCounter 2 (Limit=1038336 TPApp-PID=2619)
^[[A^[[A^[[A^C[Fri, 13 Dec 2024 12:33:31 GMT] INFO SIGINT received.
[Fri, 13 Dec 2024 12:33:31 GMT] INFO Closing listening udp 0.0.0.0:514
[Fri, 13 Dec 2024 12:33:31 GMT] INFO Closing stdout
[Fri, 13 Dec 2024 12:33:31 GMT] INFO Closing output to HEP udp to 127.0.0.1:9060
[Fri, 13 Dec 2024 12:33:31 GMT] INFO Closing agent
[Fri, 13 Dec 2024 12:33:31 GMT] INFO Quitting.

If I set debug to true in the config file I can see SIP messages in the console, just part of it below:

UNKNOWN 665997:5:29 (N     2387) (#1202)gwSession[Allocated]. Handle:00007F43C3332730; Global session ID: 33bcacfceaf9a3c7
DEBUG <157>[S=2468] [SID=665997:5:29]  (N     2413) ---- Outgoing SIP Message to 192.168.3.115:48083 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ---- [Time:13-12@12:38:18.492] [3644]
[Fri, 13 Dec 2024 12:38:21 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     2413) ---- Outgoing SIP Message to 192.168.3.115:48083 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
Routing SIP Session 665997:5:29
UNKNOWN 665997:5:29 (N     2387) (#1202)gwSession[Allocated]. Handle:00007F43C3332730; Global session ID: 33bcacfceaf9a3c7
DEBUG <157>[S=2469] [SID=665997:5:29]  PUBLISH sip:+48605555483@93.177.90.248:48083;transport=udp;rinstance=804af2bc01e56fe2 SIP/2.0
Via: SIP/2.0/UDP 192.168.3.250:5060;branch=z9hG4bKac1997274109
Max-Forwards: 69
From: "+48605555483" <sip:+48605555483@192.168.3.250;transport=udp>;tag=1c934908525
To: "+48605555483" <sip:+48605555483@192.168.3.250;transport=udp>
Call-ID: 23882985113122024123818@192.168.3.250
CSeq: 1 PUBLISH
Event: presence
Expires: 600
User-Agent: Mediant SW/v.7.40A.500.781
Allow-Events: presence, kpml, talk
Content-Type: application/pidf+xml
Content-Length: 277

<?xml version="1.0" encoding="UTF-8"?>
<presence xmlns="urn:ietf:params:xml:ns:pidf"
          entity="sip:+48605555483@192.168.3.250;transport=UDP">
  <tuple id="+48605555483" >
     <status><basic>open</basic></status>
     <note>Online</note>
  </tuple>
</presence>
 [Time:13-12@12:38:18.492] [3645]
Routing SIP Session 665997:5:29
UNKNOWN 665997:5:29 (N     2387) (#1202)gwSession[Allocated]. Handle:00007F43C3332730; Global session ID: 33bcacfceaf9a3c7
DEBUG <157>[S=2470] [SID=665997:5:29]  (N     2414) ---- Incoming SIP Message from 192.168.3.115:48083 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ---- [Time:13-12@12:38:18.507] [3646]
[Fri, 13 Dec 2024 12:38:21 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     2414) ---- Incoming SIP Message from 192.168.3.115:48083 to SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
Routing SIP Session 665997:5:29
UNKNOWN 665997:5:29 (N     2387) (#1202)gwSession[Allocated]. Handle:00007F43C3332730; Global session ID: 33bcacfceaf9a3c7
DEBUG <157>[S=2471] [SID=665997:5:29]  SIP/2.0 405 Method Not Allowed
Via: SIP/2.0/UDP 192.168.3.250:5060;branch=z9hG4bKac1997274109
To: "+48605555483"<sip:+48605555483@192.168.3.250;transport=udp>;tag=4e3f6321
From: "+48605555483" <sip:+48605555483@192.168.3.250;transport=udp>;tag=1c934908525
Call-ID: 23882985113122024123818@192.168.3.250
CSeq: 1 PUBLISH
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Content-Length: 0

 [Time:13-12@12:38:18.507] [3647]
Routing SIP Session 665997:5:29
UNKNOWN 665997:5:29 (N     2387) (#1202)gwSession[Allocated]. Handle:00007F43C3332730; Global session ID: 33bcacfceaf9a3c7
DEBUG <157>[S=2472] [SID=665997:5:29]  (N     2415) RtxMngr::Remove 1 PUBLISH, TU: AcSIPDialog(#14155) [Time:13-12@12:38:18.507] [3648]
Routing SIP Session 665997:5:29
UNKNOWN 665997:5:29 (N     2387) (#1202)gwSession[Allocated]. Handle:00007F43C3332730; Global session ID: 33bcacfceaf9a3c7
DEBUG <157>[S=2473] [SID=665997:5:29]  (N     2416) AcSIPDialog(#14155): Handling 405 in state DialogInitiated [Time:13-12@12:38:18.507] [3649]
Routing SIP Session 665997:5:29
UNKNOWN 665997:5:29 (N     2387) (#1202)gwSession[Allocated]. Handle:00007F43C3332730; Global session ID: 33bcacfceaf9a3c7
DEBUG <157>[S=2474] [SID=665997:5:29]  (N     2417) SBCGeneralResponseData: (#906)AcSBCDialogAPI -> (#906)SIPSBCDialogLeg [Time:13-12@12:38:18.507] [3650]
Routing SIP Session 665997:5:29
UNKNOWN 665997:5:29 (N     2387) (#1202)gwSession[Allocated]. Handle:00007F43C3332730; Global session ID: 33bcacfceaf9a3c7
DEBUG <157>[S=2475] [SID=665997:5:29]  (N     2418) AcSIPDialog(#14155): Handling DIALOG_DISCONNECT_REQ in state DialogInitiated [Time:13-12@12:38:18.507] [3651]
Routing SIP Session 665997:5:29
UNKNOWN 665997:5:29 (N     2387) (#1202)gwSession[Allocated]. Handle:00007F43C3332730; Global session ID: 33bcacfceaf9a3c7
DEBUG <157>[S=2476] [SID=665997:5:29]  (N     2419) States: (#14155)AcSIPDialog[DialogInitiated->DialogDisconnected]
        (#14155)AcSIPDialog[Deallocated]
        (#14155)AcSIPDialog[DialogDisconnected->DialogIdle] [Time:13-12@12:38:18.507] [3652]
Routing SIP Session 665997:5:29
UNKNOWN 665997:5:29 (N     2387) (#1202)gwSession[Allocated]. Handle:00007F43C3332730; Global session ID: 33bcacfceaf9a3c7
DEBUG <157>[S=2477] [SID=665997:5:29]  (N     2420) RELEASE_EV: (#906)SIPSBCDialogLeg -> (#900)SBCDialog[Initiated->Disconnecting]
        -> (#3083)CallPlacement [Time:13-12@12:38:18.507] [3653]
Routing SIP Session 665997:5:29
UNKNOWN 665997:5:29 (N     2387) (#1202)gwSession[Allocated]. Handle:00007F43C3332730; Global session ID: 33bcacfceaf9a3c7
DEBUG <157>[S=2478] [SID=665997:5:29]  (N     2421) (#4621)SBCRoutesIterator: Failed. Reason: Route ended. No alt route, Last route entry: 1 [Time:13-12@12:38:18.507] [3654]
Routing SIP Session 665997:5:29
UNKNOWN 665997:5:29 (N     2387) (#1202)gwSession[Allocated]. Handle:00007F43C3332730; Global session ID: 33bcacfceaf9a3c7
DEBUG <157>[S=2479] [SID=665997:5:29]  (N     2422) States: (#4621)SBCRoutesIterator[AlternativeRouting->End] [Time:13-12@12:38:18.507] [3655]
Routing SIP Session 665997:5:29
UNKNOWN 665997:5:29 (N     2387) (#1202)gwSession[Allocated]. Handle:00007F43C3332730; Global session ID: 33bcacfceaf9a3c7
DEBUG <157>[S=2480] [SID=665997:5:29]  (N     2423) (#4621)SBCRoutesIterator::Ended, No Next route found [Time:13-12@12:38:18.507] [3656]
Routing SIP Session 665997:5:29
UNKNOWN 665997:5:29 (N     2387) (#1202)gwSession[Allocated]. Handle:00007F43C3332730; Global session ID: 33bcacfceaf9a3c7
DEBUG <157>[S=2481] [SID=665997:5:29]  (N     2424) States: (#3083)CallPlacement[Initiated->End] [Time:13-12@12:38:18.507] [3657]
Routing SIP Session 665997:5:29
UNKNOWN 665997:5:29 (N     2387) (#1202)gwSession[Allocated]. Handle:00007F43C3332730; Global session ID: 33bcacfceaf9a3c7
DEBUG <157>[S=2482] [SID=665997:5:29]  (N     2425) RELEASE_EV: (#900)SBCDialog -> (#902)SBCEndPoint[Initiated->Releasing]
        -> (#450)SBCController[Establishing->Disconnecting]
        -> (#901)SBCEndPoint[Initiated->Releasing]
        -> (#901)SBCDialog[Initiated->Disconnecting]
        -> (#907)SIPSBCDialogLeg [Time:13-12@12:38:18.507] [3658]
Routing SIP Session 665997:5:29
UNKNOWN 665997:5:29 (N     2387) (#1202)gwSession[Allocated]. Handle:00007F43C3332730; Global session ID: 33bcacfceaf9a3c7
DEBUG <157>[S=2483] [SID=665997:5:29]  (N     2426) AcSIPDialog(#14156): Handling GENERAL_RESPONSE_REQ in state DialogInitiated [Time:13-12@12:38:18.507] [3659]
Routing SIP Session 665997:5:29
UNKNOWN 665997:5:29 (N     2387) (#1202)gwSession[Allocated]. Handle:00007F43C3332730; Global session ID: 33bcacfceaf9a3c7
DEBUG <157>[S=2484] [SID=665997:5:29]  (N     2427) ---- Outgoing SIP Message to 192.168.3.115:48083 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ---- [Time:13-12@12:38:18.507] [3660]
[Fri, 13 Dec 2024 12:38:21 GMT] INFO Incomplete SIP Message no more to add at this time, will cache (N     2427) ---- Outgoing SIP Message to 192.168.3.115:48083 from SIPInterface #0 (SIPInterface_0) UDP TO(#0) ----
Routing SIP Session 665997:5:29
UNKNOWN 665997:5:29 (N     2387) (#1202)gwSession[Allocated]. Handle:00007F43C3332730; Global session ID: 33bcacfceaf9a3c7
DEBUG <157>[S=2485] [SID=665997:5:29]  SIP/2.0 405 Method Not Allowed
Via: SIP/2.0/UDP 93.177.90.248:48083;branch=z9hG4bK-524287-1---d5558c7fede39172
From: "+48605555483" <sip:+48605555483@192.168.3.250;transport=udp>;tag=2d33df7a
To: "+48605555483" <sip:+48605555483@192.168.3.250;transport=udp>;tag=4e3f6321
Call-ID: bV85x1mKMHplHA-7cHttHw..
CSeq: 1 PUBLISH

Does it make any sense?

[floo94]

same here... I can see with debug activated and output of the hep files that only a few Syslog SIP messages are recognised.
Both with 7.2 and 7.4
Unfortunately I do not have the ability to set up a development environment and debug this myself. however, I can provide logs if required

[Dletta]

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

Do you see any messages through the stdout? This would indicated you are not getting any complete sip messages.

Ideally if we could have a small tcpdup or ngrep output of some of the traffic, we can have a closer look at figuring out why we don't correctly parse some of the sip messages. For example:

[Fri, 13 Dec 2024 12:38:21 GMT] INFO Incomplete SIP Message no more to add at this time, will cache

Indicates that we failed to see the message completely, even though I can see the message looking complete.

[sctomko]

I am also having this issue. on 7.40.501.141

I'm finding that with newer versions and syslog optimization off, larger SIP messages are now consuming 3 or more syslog event messages where the first SIP message is Audiocodes SIP metadata (from IP to Interface), the second is SIP message/message body until the maximum size is reached, then a third for any fragmented messages left over.

I believe this would have worked with 2 fragments corresponding to a session, but need dev confirmation on that.

Is the fragment/buffer functions only picking up the very next seq/sid in the session buffer, can it support 3 fragmented messages at once?

[lmangani]

@sctomko any chance you could provide some sample input?

[sctomko]

@lmangani can I get a sample to you in a secure manner?