QoS Report - Githubissues

bmgante commented 4 years ago

Hello,

I am using hefix.js to collect IPFIX from Oracle SBCs and convert them into HEP. Then, i use heplify-server to store data into homer database.

I´ve attached some messages from hefix.js debug output (both ipfix and hep debug enabled), to find a message related to QOS REPORT just search by 268: QOS REPORT on attached log.

The HEP is then processed by heplify and below there´s the log related to an QOS message database insertion. As you can see "RAW" column is being populated with "[object Object]". On the Homer side, i´ve created a mapping to get data from ID 35, a exact copy of default RTP-FULL-REPORT (ID 34) but with ID changed to 35.

The messages are then shown on the grid using this template but when clicking on correlation id nothing is loaded with "Uknown error" due to the RAW data being just [object Object].

2020-05-13T15:54:54+01:00 DBG [sql] COPY hep_proto_35_default(sid,create_date,protocol_header,data_header,raw) FROM STDIN

[3898c0b72c1114e02da7f07b4b72c51c@10.0.11.203:5060 2020-05-13T15:54:53.000134+01:00 {"protocolFamily":2,"protocol":17,"srcIp":"127.0.0.1","dstIp":"127.0.0.1","srcPort":0,"dstPort":0,"timeSeconds":1589381693,"timeUseconds":134,"payloadType":35,"captureId":"2017","capturePass":"oracme","correlation_id":"3898c0b72c1114e02da7f07b4b72c51c@10.0.11.203:5060"} {"node":"2017","proto":"rtcpxr"} [object Object]

hepfix.log

Homer postgres database:

lmangani commented 4 years ago

"[object Object]" is the default string representation of a JSON object when printed badly. This means raw does not contain a string but a JSON object and should be parsed to string before writing it as such. Type 34 and 35 are not the same - specifically type 35 is designed to carry final measurements and includes a MOS field in the HEP headers so the mapping would not achieve the desired result.

Could you describe your expected results? Mind this is completely unsupported other than through community input, and since we never had or have commercial equipment from this vendor you will have to provide a PCAP capture the raw HEP traffic between HEPfix and the HEP Server for us to investigate.

Thanks!

lmangani commented 4 years ago

BTW there's a chance the data in the DB is actually right. Please do a row dump and attach it here for review.

bmgante commented 4 years ago

Hello @lmangani First of all thanks for your feedback. Indeed this is the first time i am working with IPFIX and HEP formats. This specific Oracle equipment only provides SIP signalling and QoS/RTP reports through IPFIX that´s why i am trying to use this tool to convert them to HEP and was in the hope i could see that information on Homer GUI like we are doing for SIP TCP/UDP signalling (which is just working fine).

The pre-defined templaes Oracle SBC are using mentioned on https://docs.oracle.com/cd/E95619_01/html/esbc_ecz810_monitoring/GUID-DD7809FA-229B-4749-9CBA-23D2E03115F0.htm

From the tests i´ve already done seems that the template being sent by SBC is "268 | QOS RTP/RTCP" which is then sent to heplify-server which is storing it on DB with ID 35.

From the HEPFIX debug we can see something like:

RTP-INC { CORRELATION_ID: '3d78b7b1598f1bd901da8a3038f79c15@10.0.11.203:5060', RTP_SIP_CALL_ID: '3d78b7b1598f1bd901da8a3038f79c15@10.0.11.203:5060', REPORT_TS: 0, TL_BYTE: 0, SKEW: 0, TOTAL_PK: 0, EXPECTED_PK: 0, PACKET_LOSS: 0, SEQ: 0, JITTER: 0, MAX_JITTER: 0, MEAN_JITTER: 0, DELTA: 0, MAX_DELTA: 0, MAX_SKEW: 0, MIN_MOS: 0, MEAN_MOS: 0, MOS: 0, RFACTOR: 0, MIN_RFACTOR: 0, MEAN_RFACTOR: 0, SRC_IP: '0.0.0.0', SRC_PORT: 0, DST_IP: '10.57.252.5', DST_PORT: 0, SRC_MAC: '00-00-00-00-00-00', DST_MAC: '00-00-00-00-00-00', OUT_ORDER: 0, SSRC_CHG: 0, CODEC_PT: 1, CLOCK: 8000, CODEC_NAME: 1, DIR: 0, REPORT_NAME: 'RTP:peering.denphonefc:core.den.ams', PARTY: 0, TYPE: 'PERIODIC' }

RTP-OUT { CORRELATION_ID: '3d78b7b1598f1bd901da8a3038f79c15@10.0.11.203:5060', RTP_SIP_CALL_ID: '3d78b7b1598f1bd901da8a3038f79c15@10.0.11.203:5060', REPORT_TS: 0, TL_BYTE: 0, SKEW: 0, TOTAL_PK: 0, EXPECTED_PK: 0, PACKET_LOSS: 0, SEQ: 0, JITTER: 0, MAX_JITTER: 0, MEAN_JITTER: 0, DELTA: 0, MAX_DELTA: 0, MAX_SKEW: 0, MIN_MOS: 0, MEAN_MOS: 0, MOS: 0, RFACTOR: 0, MIN_RFACTOR: 0, MEAN_RFACTOR: 0, SRC_IP: '10.57.252.5', SRC_PORT: 63460, DST_IP: '10.0.11.203', DST_PORT: 17368, SRC_MAC: '00-00-00-00-00-00', DST_MAC: '00-00-00-00-00-00', OUT_ORDER: 0, SSRC_CHG: 0, CODEC_PT: 1, CLOCK: 8000, CODEC_NAME: 1, DIR: 1, REPORT_NAME: 'RTP:core.den.ams:peering.denphonefc', PARTY: 1, TYPE: 'PERIODIC' }

I´ll capture a tcpdump between HEPFIX and HEPLIFY asap and will share it so maybe you can help on this.

Thanks

lmangani commented 4 years ago

Try add a debug line before the 268 message is parsed and confirm what's in there.

bmgante commented 4 years ago

BTW there's a chance the data in the DB is actually right. Please do a row dump and attach it here for review.

Regarding this i´ve tried to dump the table from homer_data using pgadmin but it´s not possible:

ERROR:  cannot copy from partitioned table "hep_proto_35_default"
HINT:  Try the COPY (SELECT ...) TO variant.

Then i tried through command line using COPY (SELECT) but the export is the same.

postgres=# \connect homer_data
homer_data=# \copy (select * from public.hep_proto_35_default) to '/var/lib/pgsql/homer_dump.csv' csv;
COPY 14

Dump:

-bash-4.2$ cat homer_dump.csv
2,660bf5995189fcdf591370df66bf42cf@10.0.11.203:5060,2020-05-13 14:50:39.000762+01,"{""dstIp"": ""127.0.0.1"", ""srcIp"": ""127.0.0.1"", ""dstPort"": 0, ""srcPort"": 0, ""protocol"": 17, ""captureId"": ""2017"", ""capturePass"": ""oracme"", ""payloadType"": 35, ""timeSeconds"": 1589377839, ""timeUseconds"": 762, ""correlation_id"": ""660bf5995189fcdf591370df66bf42cf@10.0.11.203:5060"", ""protocolFamily"": 2}","{""node"": ""2017"", ""proto"": ""rtcpxr""}",[object Object]
3,1c9f230b4321622617ed12106426f263@10.0.11.203:5060,2020-05-13 15:48:26.000739+01,"{""dstIp"": ""127.0.0.1"", ""srcIp"": ""127.0.0.1"", ""dstPort"": 0, ""srcPort"": 0, ""protocol"": 17, ""captureId"": ""2017"", ""capturePass"": ""oracme"", ""payloadType"": 35, ""timeSeconds"": 1589381306, ""timeUseconds"": 739, ""correlation_id"": ""1c9f230b4321622617ed12106426f263@10.0.11.203:5060"", ""protocolFamily"": 2}","{""node"": ""2017"", ""proto"": ""rtcpxr""}",[object Object]
5,3898c0b72c1114e02da7f07b4b72c51c@10.0.11.203:5060,2020-05-13 15:54:53.000134+01,"{""dstIp"": ""127.0.0.1"", ""srcIp"": ""127.0.0.1"", ""dstPort"": 0, ""srcPort"": 0, ""protocol"": 17, ""captureId"": ""2017"", ""capturePass"": ""oracme"", ""payloadType"": 35, ""timeSeconds"": 1589381693, ""timeUseconds"": 134, ""correlation_id"": ""3898c0b72c1114e02da7f07b4b72c51c@10.0.11.203:5060"", ""protocolFamily"": 2}","{""node"": ""2017"", ""proto"": ""rtcpxr""}",[object Object]
6,3898c0b72c1114e02da7f07b4b72c51c@10.0.11.203:5060,2020-05-13 15:54:53.000135+01,"{""dstIp"": ""127.0.0.1"", ""srcIp"": ""127.0.0.1"", ""dstPort"": 0, ""srcPort"": 0, ""protocol"": 17, ""captureId"": ""2017"", ""capturePass"": ""oracme"", ""payloadType"": 35, ""timeSeconds"": 1589381693, ""timeUseconds"": 135, ""correlation_id"": ""3898c0b72c1114e02da7f07b4b72c51c@10.0.11.203:5060"", ""protocolFamily"": 2}","{""node"": ""2017"", ""proto"": ""rtcpxr""}",[object Object]
7,3898c0b72c1114e02da7f07b4b72c51c@10.0.11.203:5060,2020-05-13 15:55:25.000273+01,"{""dstIp"": ""127.0.0.1"", ""srcIp"": ""127.0.0.1"", ""dstPort"": 0, ""srcPort"": 0, ""protocol"": 17, ""captureId"": ""2017"", ""capturePass"": ""oracme"", ""payloadType"": 35, ""timeSeconds"": 1589381725, ""timeUseconds"": 273, ""correlation_id"": ""3898c0b72c1114e02da7f07b4b72c51c@10.0.11.203:5060"", ""protocolFamily"": 2}","{""node"": ""2017"", ""proto"": ""rtcpxr""}",[object Object]
10,3d78b7b1598f1bd901da8a3038f79c15@10.0.11.203:5060,2020-05-13 16:45:16.000676+01,"{""dstIp"": ""127.0.0.1"", ""srcIp"": ""127.0.0.1"", ""dstPort"": 0, ""srcPort"": 0, ""protocol"": 17, ""captureId"": ""2017"", ""capturePass"": ""oracme"", ""payloadType"": 35, ""timeSeconds"": 1589384716, ""timeUseconds"": 676, ""correlation_id"": ""3d78b7b1598f1bd901da8a3038f79c15@10.0.11.203:5060"", ""protocolFamily"": 2}","{""node"": ""2017"", ""proto"": ""rtcpxr""}",[object Object]
12,3d78b7b1598f1bd901da8a3038f79c15@10.0.11.203:5060,2020-05-13 16:45:48.000723+01,"{""dstIp"": ""127.0.0.1"", ""srcIp"": ""127.0.0.1"", ""dstPort"": 0, ""srcPort"": 0, ""protocol"": 17, ""captureId"": ""2017"", ""capturePass"": ""oracme"", ""payloadType"": 35, ""timeSeconds"": 1589384748, ""timeUseconds"": 723, ""correlation_id"": ""3d78b7b1598f1bd901da8a3038f79c15@10.0.11.203:5060"", ""protocolFamily"": 2}","{""node"": ""2017"", ""proto"": ""rtcpxr""}",[object Object]
14,53f3c898342756603f289cbc7f854f63@10.0.11.203:5060,2020-05-13 17:06:11.00059+01,"{""dstIp"": ""127.0.0.1"", ""srcIp"": ""127.0.0.1"", ""dstPort"": 0, ""srcPort"": 0, ""protocol"": 17, ""captureId"": ""2017"", ""capturePass"": ""oracme"", ""payloadType"": 35, ""timeSeconds"": 1589385971, ""timeUseconds"": 590, ""correlation_id"": ""53f3c898342756603f289cbc7f854f63@10.0.11.203:5060"", ""protocolFamily"": 2}","{""node"": ""2017"", ""proto"": ""rtcpxr""}",[object Object]
8,3898c0b72c1114e02da7f07b4b72c51c@10.0.11.203:5060,2020-05-13 15:55:25.000273+01,"{""dstIp"": ""127.0.0.1"", ""srcIp"": ""127.0.0.1"", ""dstPort"": 0, ""srcPort"": 0, ""protocol"": 17, ""captureId"": ""2017"", ""capturePass"": ""oracme"", ""payloadType"": 35, ""timeSeconds"": 1589381725, ""timeUseconds"": 273, ""correlation_id"": ""3898c0b72c1114e02da7f07b4b72c51c@10.0.11.203:5060"", ""protocolFamily"": 2}","{""node"": ""2017"", ""proto"": ""rtcpxr""}",[object Object]
9,3d78b7b1598f1bd901da8a3038f79c15@10.0.11.203:5060,2020-05-13 16:45:16.000677+01,"{""dstIp"": ""127.0.0.1"", ""srcIp"": ""127.0.0.1"", ""dstPort"": 0, ""srcPort"": 0, ""protocol"": 17, ""captureId"": ""2017"", ""capturePass"": ""oracme"", ""payloadType"": 35, ""timeSeconds"": 1589384716, ""timeUseconds"": 677, ""correlation_id"": ""3d78b7b1598f1bd901da8a3038f79c15@10.0.11.203:5060"", ""protocolFamily"": 2}","{""node"": ""2017"", ""proto"": ""rtcpxr""}",[object Object]
11,3d78b7b1598f1bd901da8a3038f79c15@10.0.11.203:5060,2020-05-13 16:45:48.000724+01,"{""dstIp"": ""127.0.0.1"", ""srcIp"": ""127.0.0.1"", ""dstPort"": 0, ""srcPort"": 0, ""protocol"": 17, ""captureId"": ""2017"", ""capturePass"": ""oracme"", ""payloadType"": 35, ""timeSeconds"": 1589384748, ""timeUseconds"": 724, ""correlation_id"": ""3d78b7b1598f1bd901da8a3038f79c15@10.0.11.203:5060"", ""protocolFamily"": 2}","{""node"": ""2017"", ""proto"": ""rtcpxr""}",[object Object]
13,53f3c898342756603f289cbc7f854f63@10.0.11.203:5060,2020-05-13 17:06:11.00059+01,"{""dstIp"": ""127.0.0.1"", ""srcIp"": ""127.0.0.1"", ""dstPort"": 0, ""srcPort"": 0, ""protocol"": 17, ""captureId"": ""2017"", ""capturePass"": ""oracme"", ""payloadType"": 35, ""timeSeconds"": 1589385971, ""timeUseconds"": 590, ""correlation_id"": ""53f3c898342756603f289cbc7f854f63@10.0.11.203:5060"", ""protocolFamily"": 2}","{""node"": ""2017"", ""proto"": ""rtcpxr""}",[object Object]
1,660bf5995189fcdf591370df66bf42cf@10.0.11.203:5060,2020-05-13 14:50:39.000763+01,"{""dstIp"": ""127.0.0.1"", ""srcIp"": ""127.0.0.1"", ""dstPort"": 0, ""srcPort"": 0, ""protocol"": 17, ""captureId"": ""2017"", ""capturePass"": ""oracme"", ""payloadType"": 35, ""timeSeconds"": 1589377839, ""timeUseconds"": 763, ""correlation_id"": ""660bf5995189fcdf591370df66bf42cf@10.0.11.203:5060"", ""protocolFamily"": 2}","{""node"": ""2017"", ""proto"": ""rtcpxr""}",[object Object]
4,1c9f230b4321622617ed12106426f263@10.0.11.203:5060,2020-05-13 15:48:26.00074+01,"{""dstIp"": ""127.0.0.1"", ""srcIp"": ""127.0.0.1"", ""dstPort"": 0, ""srcPort"": 0, ""protocol"": 17, ""captureId"": ""2017"", ""capturePass"": ""oracme"", ""payloadType"": 35, ""timeSeconds"": 1589381306, ""timeUseconds"": 740, ""correlation_id"": ""1c9f230b4321622617ed12106426f263@10.0.11.203:5060"", ""protocolFamily"": 2}","{""node"": ""2017"", ""proto"": ""rtcpxr""}",[object Object]

lmangani commented 4 years ago

ACK. Please set debug mode in sipfix, or add a custom line logging the qos variable before emission

bmgante commented 4 years ago

ACK. Please set debug mode in sipfix, or add a custom line logging the qos variable before emission

Are you talking about hepfix debug? I have the following config.js. Any other debug should be enabled?

[root@pocldnipfix01 hepfix.js]# cat config.js
var config = {
  ipfix_config: {
    debug: true,
    qos: true,
    sip: true,
    IPFIX_PORT: 4739
  },
  hep_config: {
    debug: true,
    HEP_SERVER: '127.0.0.1',
    HEP_PORT: 9060,
    HEP_ID: 2017,
    HEP_PASS: 'oracme'
  }
};

module.exports = config;

This debug level creates the following output: hepfix.log

On thatf file we have QOS messages for the following correlation ids:

3d78b7b1598f1bd901da8a3038f79c15@10.0.11.203:5060
53f3c898342756603f289cbc7f854f63@10.0.11.203:5060

If we search for that correlation id on Homer we have there the tab "QoS" but of course the data is corrupted due to the "[object Object]".

Regarding the tcpdump between hepfix and heplify I´ll be able to provide it this afternoon.

Thanks

lmangani commented 4 years ago

The qos decoder fails - no way to debug without the original IPFIX traffic

268: QOS REPORT
{ CallID: '3d78b7b1598f1bd901da8a3038f79c15@10.0.11.203:5060' }
{ type: 'HEP',
  version: 3,
  payload_type: 'JSON',
  captureId: 2017,
  capturePass: 'oracme',
  ip_family: 2,
  protocol: 17,
  proto_type: 35,
  srcIp: undefined,
  dstIp: undefined,
  srcPort: undefined,
  dstPort: undefined,
  correlation_id: '3d78b7b1598f1bd901da8a3038f79c15@10.0.11.203:5060',
  mos: 0,
  time_sec: 1589384716,
  time_usec: 676 }

You might want to try with horaclifix see if its parsed there or dig into the originals if you own the device.

lmangani commented 4 years ago

btw i see some type 34 statistics are correctly parsed here - are those displayed?

RTP-OUT { CORRELATION_ID: '53f3c898342756603f289cbc7f854f63@10.0.11.203:5060',
  RTP_SIP_CALL_ID: '53f3c898342756603f289cbc7f854f63@10.0.11.203:5060',
  REPORT_TS: 0,
  TL_BYTE: 11792,
  SKEW: 0,
  TOTAL_PK: 88,
  EXPECTED_PK: 107,
  PACKET_LOSS: 19,
  SEQ: 0,
  JITTER: 225773,
  MAX_JITTER: 991495617,
  MEAN_JITTER: 225773,
  DELTA: 0,
  MAX_DELTA: 0,
  MAX_SKEW: 0,
  MIN_MOS: 275,
  MEAN_MOS: 275,
  MOS: 275,
  RFACTOR: 5349,
  MIN_RFACTOR: 5349,
  MEAN_RFACTOR: 5349,
  SRC_IP: '10.57.252.5',
  SRC_PORT: 63364,
  DST_IP: '10.0.11.203',
  DST_PORT: 14764,
  SRC_MAC: '00-00-00-00-00-00',
  DST_MAC: '00-00-00-00-00-00',
  OUT_ORDER: 0,
  SSRC_CHG: 0,
  CODEC_PT: 1,
  CLOCK: 8000,
  CODEC_NAME: 1,
  DIR: 1,
  REPORT_NAME: 'RTP:core.den.ams:peering.denphonefc',
  PARTY: 1,
  TYPE: 'PERIODIC' }

bmgante commented 4 years ago

No, i can´t see nothing on homer side. I can provide later today a tcpdump of the ipfix data reaching the hepfix on port 4739 and another tcpdump for the HEP between hepfix and heplify-server (port 9060).

ID 34 statistics seem that are not being sent to homer maybe due to parsing issues, as we can see below we have several "undefined" and correlation_id empty. On the other hand, on homer postgres dabtase, table ID 35 is created with that issues with the "Object" but we have no data inserted into table ID 34.

undefined { type: 'HEP', version: 3, payload_type: 'JSON', captureId: 2017, capturePass: 'oracme', ip_family: 2, protocol: 17, proto_type: 34, srcIp: undefined, dstIp: undefined, srcPort: undefined, dstPort: undefined, correlation_id: '', time_sec: 1589381306, time_usec: 743 }

I´ve also attached the heplify-server log with debug mode enabled fot the case it could help:

LogDbg                = "hep,sql,loki"
LogLvl                = "debug"

heplify-server.log

lmangani commented 4 years ago

@bmgante no need for the HEP trace as the issue is before HEP comes in apparently. Please test using the new version and attach a fresh hepfix log, checking for undefined in report types 268 on the next round. Also make sure you're running the latest H7.7 release as those reports might not otherwise displayed properly.

bmgante commented 4 years ago

@bmgante no need for the HEP trace as the issue is before HEP comes in apparently. Please test using the new version and attach a fresh hepfix log, checking for undefined in report types 268 on the next round. Also make sure you're running the latest H7.7 release as those reports might not otherwise displayed properly.

I am using Homer 7.7.032 (installed it on last March).

Ok, I´ll try the new hepfix version and let you know.

bmgante commented 4 years ago

@lmangani please just confirm if you want both "ipfix_config" and "hep_config" debug enabled or only one of them to turn the output easier to read. Currently i have both of them enabled as below:


[root@pocldnipfix01 hepfix.js]# cat config.js
var config = {
  ipfix_config: {
    debug: true,
    qos: true,
    sip: true,
    IPFIX_PORT: 4739
  },
  hep_config: {
    debug: true,
    HEP_SERVER: '127.0.0.1',
    HEP_PORT: 9060,
    HEP_ID: 2017,
    HEP_PASS: 'oracme'
  }
};

module.exports = config;

New version of hepfix is installed and i am just waiting to get a time slot with SBC owner to run some tests.

lmangani commented 4 years ago

same logset as previously in order to compare - so both is best

bmgante commented 4 years ago

Hi @lmangani I was able to capture some data with the new hepfix.js version.

Searching by 268: i got:

268: QOS REPORT
RangeError: Index out of range
    at checkOffset (buffer.js:831:11)
    at Buffer.readUInt8 (buffer.js:869:5)
    at DecodeStream.(anonymous function) [as readUInt8] (/root/node_modules/restructure/src/DecodeStream.js:38:35)
    at NumberT.decode (/root/node_modules/restructure/src/Number.js:24:38)
    at Struct._parseFields (/root/node_modules/restructure/src/Struct.js:53:22)
    at Struct.decode (/root/node_modules/restructure/src/Struct.js:18:12)
    at Object.exports.StatsQos (/root/node_modules/sipfix/index.js:307:24)
    at fixHandler (/root/node_modules/hepfix.js/hepfix.js:197:21)
    at fixHandler (/root/node_modules/hepfix.js/hepfix.js:112:4)
    at fixHandler (/root/node_modules/hepfix.js/hepfix.js:145:4)
Invalid/Unsupported Type:  undefined
Invalid/Unsupported Type:  undefined

Full hepfix debug log file: hepfix_15May.log

The output from heplify-server debug was the same with [object Object] for raw column:

2020-05-15T10:14:11+01:00 DBG  [sql] COPY hep_proto_35_default(sid,create_date,protocol_header,data_header,raw) FROM STDIN

[08ee44ec6d0c66040ca2c1ca50445edb@10.0.11.203:5060 2020-05-15T10:14:10.0007+01:00 {"protocolFamily":2,"protocol":17,"srcIp":"127.0.0.1","dstIp":"127.0.0.1","srcPort":0,"dstPort":0,"timeSeconds":1589534050,"timeUseconds":700,"payloadType":35,"captureId":"2017","capturePass":"oracme","correlation_id":"08ee44ec6d0c66040ca2c1ca50445edb@10.0.11.203:5060"} {"node":"2017","proto":"rtcpxr"} [object Object]]

Full heplify-server debug log file: heplify-server.log

I´ve also captured a pcap on ports 4739 (ipfix input) and 9060 (hep) for the same time window.

ipfix_hep_15May.zip

Note that on SBC side (IPFIX configuration) we have now tls_profille enabled, not sure if it has any imapct or not on hepfix side (but it is still properly decoding sip signalling and its available on homer). The config is as below:

            comm-monitor
                state                                       enabled
                sbc-grp-id                              0
                tls-profile                               enabled 
                qos-enable                             enabled
                interim-qos-update                enabled
                monitor-collector
                        address                                 10.21.12.152
                        port                                       4739
                        network-interface                 wancom0:0
                options

bmgante commented 4 years ago

hepfix is still collecting so i´ve attached a new and more complete log with more occurrences where we can find errors like the one below:

hepfix_15May_v2.log

268: QOS MULTI-MESSAGE TRY NEXT
RangeError: Index out of range
    at checkOffset (buffer.js:831:11)
    at Buffer.readUInt32BE (buffer.js:905:5)
    at DecodeStream.(anonymous function) [as readUInt32BE] (/root/node_modules/restructure/src/DecodeStream.js:38:35)
    at NumberT.decode (/root/node_modules/restructure/src/Number.js:24:38)
    at Struct._parseFields (/root/node_modules/restructure/src/Struct.js:53:22)
    at Struct.decode (/root/node_modules/restructure/src/Struct.js:18:12)
    at Object.exports.readHeader (/root/node_modules/sipfix/index.js:266:22)
    at fixHandler (/root/node_modules/hepfix.js/hepfix.js:56:22)
    at fixHandler (/root/node_modules/hepfix.js/hepfix.js:225:5)
    at fixHandler (/root/node_modules/hepfix.js/hepfix.js:112:4)
UNDECODED MESSAGE:  <Buffer 00 0a 01 81 5e be 5e 85 00 00 80 86 00>
UNDECODED MESSAGE:  <Buffer 00 00 00 01 04 01 71 5e be 5e 85 00 03 82 0f 00 00 00 00 0a 39 14 10 0a 1f 97 8c 57 cc 13 c4 58 f8 0a 00 ff 01 4e 53 49 50 2f 32 2e 30 20 32 30 30 20 ... >

lmangani commented 4 years ago

Thanks @bmgante for the complete and documented report! there is some sort of mysterious format change for stats here, will try to take a peek - in either case, the error is just for type 258 with multiple content, so everything else should be unaffected.

bmgante commented 4 years ago

Thanks @bmgante for the complete and documented report! there is some sort of mysterious format change for stats here, will try to take a peek - in either case, the error is just for type 258 with multiple content, so everything else should be unaffected.

@lmangani , you mean type 268, which is the RTP QOS template, right? Type 258 is "SIP UDP Recv Msg Sent".

Yes, the SIP signalling messages seem to be working properly. It´s just a matter of QOS template decode.

bmgante commented 4 years ago

Hello @lmangani , did you have chance to find the issue? :) Thanks in advance

lmangani commented 3 years ago

If you're still using hepfix, this PR has a good chance to fix the issue

bmgante commented 3 years ago

@lmangani indeed i am using horaclifix but noticed that we have some sip messages truncated... from my analysis seems it´s somehow related with packet fragmentation but was not able yet to understand exactly what is the problem. Are you aware of such issue? Noticed this PR implements some buffers... any chance this PR to address that truncate message issue? If yes I´d be interested to give it a try.

lmangani commented 3 years ago

If you can isolate the affected messages and provide us an ipfix pcap we can definitely catch it

bmgante commented 3 years ago

It's attached. There is a number of infix packets, some are complete some are not. Seems that all packets with setid=260 are fragmented and then we only see the part of the message in homer.

ipfix_truncated_filtered.pcap.zip

bmgante commented 3 years ago

@lmangani any chance to help me understand how to address this truncate issue?

adubovikov commented 3 years ago

@bmgante we are working on it

bmgante commented 3 years ago

Thanks for your feedback @adubovikov

bmgante commented 3 years ago

@lmangani @adubovikov tested with latest hepfix.js commit but issue is still happening. Below an example of a sip register truncated.

bmgante commented 3 years ago

Attaching some logs from hepfix and also from heplify-server that may help.

heplify-server.log hepfix.log

For example, the following error on heplify-server seems to be related to a truncated sip register, snapshot below.

2021-09-15T15:02:54+01:00 WARN parseStartLine err: received err while parsing start line: parseStartLineRequest err: request line did not split on LWS correctly "Allow: ACK,BYE,CANCEL,INFO,INVITE,MESSAGE,NOTIFY,OPTIONS,PRACK,REFER,UPDATE\r\nMax-Forwards: 70\r\nSupported: 100rel,path,replaces\r\nUser-Agent: iOS/14.3 (18C66) iPhone\r\nContent-Type: application/pidf+xml\r\nContent-Length: 615\r\n\r\n<?xml version=\"1.0\"?>\r\n<presence xmlns=\"urn:ietf:params:xml:ns:pidf\" xmlns:dm=\"urn:ietf:params:xml:ns:pidf:data-model\" xmlns:gp=\"urn:ietf:params:xml:ns:pidf:geopriv10\" xmlns:gml=\"http://www.opengis.net/gml\" xmlns:gs=\"http://www.opengis.net/pidflo/1.0\" xmlns:cl=\"urn:ietf:params:xml:ns:pidf:geopriv10:civicAddr\" entity=\"sip:+447408849492@ims.truphone.net\">\r\n<dm:device id=\"Wifi\">\r\n<gp:geopriv>\r\n<gp:location-info>\r\n<cl:civicAddress>\r\n<cl:country>PT</cl:country>\r\n</cl:civicAddress>\r\n</gp:location-info>\r\n<gp:usage-rules/>\r\n</gp:geopriv>\r\n<dm:timestamp>2021-09-15T14:02:54Z</dm:timestamp>\r\n</dm:device>\r\n</presence>\r\n" nodeID: 2263, protoType: 1, version: 2, protocol: 17, length: 839, flow: 10.176.244.83:5060->10.21.151.77:5060

sipcapture / hepfix.js

QoS Report #4