skipdefault delays processing of calls

Hi, we experience a weird issue when setting skipdefault = yes on a remote sensor: calls that match a filter rule take up to 30 min to process. It seems as if voipmonitor only starts processing calls at half hour intervals, at a quarter to or a quarter past full hours (e.g. 12:15, 12:45, etc.). Could this just be a coincidence? The other time voipmonitor starts processing the first call that matches a filter rule, is when there is a second matched call. It then processes the first, but not the second. In order for the second call to be processed, a third call would have to be matched to a filter rule (or one would have to wait up to half an hour). The following is an example of a call from our logs, which took more than 6 minutes to start processing.

This is the last log entry before the call:

Sep 16 13:38:48 x.x.x.x voipmonitor[32585]: calls[0,r:0][0,r:0] PS[C:0/-0 r:-/- S:27/20 SR:- SM:- R:0/0 A:17280] SQLq[C:0 M:0 Cl:0] heap[0|0|0] [28.3Mb/s] t0CPU[0.6%] t1CPU[1.0%] t2CPU[pb:1.4/d3.2/s27.0/rm:3.1/rh:0.1/rd:0.5/S:35.3%] tRTP_CPU[0.1%/0.1m/1t] tacCPU[0.0%] RSS/VSZ[767|1012]MB LA[0.21 0.42 0.49|8h] TLB[1] v26.21.2

Here is the next entry with the two legs of the call that matched a filter rule:

Sep 16 13:38:58 x.x.x.x voipmonitor[32585]: calls[2,r:0][2,r:0] PS[C:0/-0 r:-/- S:29/21 SR:- SM:- R:169/169 A:17580] SQLq[C:0 M:0 Cl:0] heap[0|0|0] [29.0Mb/s] t0CPU[0.6%] t1CPU[0.9%] t2CPU[pb:1.3/d3.2/s28.0/rm:3.1/rh:0.2/rd:0.9/S:36.8%] tRTP_CPU[0.2%/0.2m/1t] tacCPU[0.2%] RRD[0.1%] RSS/VSZ[767|1012]MB LA[0.25 0.42 0.49|8h] TLB[6] v26.21.2

The call ends after a couple of seconds, but both legs are still in limbo six minutes later:

Sep 16 13:45:00 x.x.x.x voipmonitor[32585]: calls[2,r:0][2,r:0] PS[C:0/-0 r:-/- S:24/19 SR:- SM:- R:0/0 A:9327] SQLq[C:0 M:0 Cl:0] heap[1|1|0] [26.2Mb/s] t0CPU[0.6%] t1CPU[0.8%] t2CPU[pb:1.1/d2.4/s48.5/rm:2.1/rh:0.1/rd:0.6/S:54.8%] tRTP_CPU[0.1%/0.1m/1t] tacCPU[0.0%] RRD[0.1%] RSS/VSZ[767|1012]MB LA[0.90 0.61 0.53|8h] TLB[5] v26.21.2

We then get failed connection with the central sensor regarding sql. It seems unrelated, as we experience these issues even without skipdefault and it does not break our setup. Anyway, it is included here for completeness.

Sep 16 13:45:08 x.x.x.x voipmonitor[32585]: sql store - y.x.x.x : 6666 - loss connection - failed read()
Sep 16 13:45:08 x.x.x.x voipmonitor[32585]: send store query error: failed read query response
Sep 16 13:45:08 x.x.x.x voipmonitor[32585]: sql store - y.x.x.x : 6666 - loss connection - failed read()
Sep 16 13:45:08 x.x.x.x voipmonitor[32585]: send store query error: failed read query response

Voipmonitor now starts processing the call:

Sep 16 13:45:10 x.x.x.x voipmonitor[32585]: start PreProcessPacket out thread extend/2041
Sep 16 13:45:10 x.x.x.x voipmonitor[32585]: calls[0,r:0][2,r:0] PS[C:0/-0 r:-/- S:19/19 SR:- SM:- R:0/0 A:41] SQLq[C:0 M:0 Cl:0] heap[3|1|0] [26.3Mb/s] t0CPU[0.5%] t1CPU[0.8%] t2CPU[pb:0.4/d0.4/s100.6/rm:0.6/rh:0.0/rd:0.3/S:102.3%] tRTP_CPU[0.1%/0.1m/1t] tacCPU[0.1%] RRD[0.1%] RSS/VSZ[767|1012]MB LA[0.92 0.62 0.54|8h] TLB[6] v26.21.2
Sep 16 13:45:11 x.x.x.x voipmonitor[32585]: next attempt 1 - query: L187:INSERT INTO files #011#011SET datehour = 2020091613, #011#011    spool_index = 0, #011#011    id_sensor = 9300,
Sep 16 13:45:11 x.x.x.x voipmonitor[32585]: next attempt 1 - query: L418::MIG:INSERT IGNORE INTO rtp_stat ( `id_sensor`,`time`,`saddr`,`mosf1_min`,`mosf1_avg`,`mosf2_mi`

Voipmonitor is done processing the call:

Sep 16 13:45:20 x.x.x.x voipmonitor[32585]: calls[0,r:0][0,r:0] PS[C:0/-0 r:-/- S:76/58 SR:- SM:- R:0/0 A:38590] SQLq[C:0 M:0 Cl:0] heap[0|0|0] [26.3Mb/s] t0CPU[0.6%] t1CPU[0.7%] t2CPU[pb:2.0/d2.4/s2.5/rm:2.5/rh:0.4/rd:0.4/S:10.2%] tRTP_CPU[0.2%/0.2m/1t] tacCPU[0.1%] RSS/VSZ[767|1020]MB LA[0.85 0.62 0.54|8h] TLB[34] v26.21.2

edit: code formatting

voipmonitor / sniffer

skipdefault delays processing of calls #68