Hi,

We are developing a project for parser and store MEGACO message by kamailio.

During the testing, we find that kamailio inserts one message only once, but there are duplicated messages in mysql datebase.

Did you meet the similar issue before?

Could you please share some information for us?

Thank you in advance.

[Environment/version]

Environment: Debian-Jessie, docker image

Version: kamialio 5.0.6 docker image.

[Description]

Kamailio stores one message by calling mysql function once, but there are two same message in DB randomly.

Function flow: core->nosip parser-> nosip store.

[Kamailio Log]

Jun 26 07:17:49 dnt02-elk-control-worker-edge-01 journal: }]#033[0;39;49m#033[0;33;49m 5(22) CRITICAL: nosip [megaco_capture.c:49]: megaco_error_code(): No error in MEGCO!

Jun 26 07:17:49 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 5(22) CRITICAL: nosip [megaco_capture.c:406]: megaco_capture(): No error code.#033[0;39;49m#033[0;33;49m 5(22) CRITICAL: nosip [megaco_capture.c:269]: megaco_capture_store(): az_megaco_tmstamp(1529997468887999)//debug log for message, this is duplicated message in mysql.

Jun 26 07:17:49 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 5(22) CRITICAL: nosip [megaco_capture.c:305]: megaco_capture_store(): insert into homer table: [megaco_capture_all_20180626]

Jun 26 07:17:49 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 5(22) CRITICAL: nosip [megaco_capture.c:308]: megaco_capture_store(): storing info...

Jun 26 07:17:50 dnt02-elk-control-worker-edge-01 journal: I0626 07:17:50.802482       1 event.go:218] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"default", Name:"homer-data-dashboard", UID:"136b3329-78f1-11e8-8d74-0050568fb61f", APIVersion:"v1", ResourceVersion:"2841229", FieldPath:""}): type: 'Warning' reason: 'ProvisioningFailed' storageclass.storage.k8s.io "glusterfs-storageclass" not found

Jun 26 07:17:50 dnt02-elk-control-worker-edge-01 journal: I0626 07:17:50.802660       1 event.go:218] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"default", Name:"homer-data-semaphore", UID:"1369de0b-78f1-11e8-8d74-0050568fb61f", APIVersion:"v1", ResourceVersion:"2841228", FieldPath:""}): type: 'Warning' reason: 'ProvisioningFailed' storageclass.storage.k8s.io "glusterfs-storageclass" not found

Jun 26 07:17:50 dnt02-elk-control-worker-edge-01 journal: I0626 07:17:50.802706       1 event.go:218] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"default", Name:"homer-data-mysql", UID:"136e804c-78f1-11e8-8d74-0050568fb61f", APIVersion:"v1", ResourceVersion:"2841231", FieldPath:""}): type: 'Warning' reason: 'ProvisioningFailed' storageclass.storage.k8s.io "glusterfs-storageclass" not found

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: I0626 07:17:51.223950       1 trace.go:76] Trace[1532720894]: "GuaranteedUpdate etcd3: *core.Endpoints" (started: 2018-06-26 07:17:48.964454076 +0000 UTC m=+1830051.184603352) (total time: 2.259414864s):

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: Trace[1532720894]: [2.259374311s] [2.258991423s] Transaction committed

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: I0626 07:17:51.224190       1 trace.go:76] Trace[557711900]: "Update /api/v1/namespaces/kube-system/endpoints/kube-scheduler" (started: 2018-06-26 07:17:48.964209184 +0000 UTC m=+1830051.184358457) (total time: 2.259905913s):

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: Trace[557711900]: [2.259791237s] [2.259619876s] Object stored in database

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: 2018-06-26 07:17:51.220413 W | wal: sync duration of 1.446041666s, expected less than 1s

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: I0626 07:17:51.225704       1 trace.go:76] Trace[656020708]: "GuaranteedUpdate etcd3: *core.Node" (started: 2018-06-26 07:17:50.573518495 +0000 UTC m=+1830052.793667844) (total time: 652.126103ms):

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: Trace[656020708]: [651.833583ms] [647.806507ms] Transaction committed

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 5(22) CRITICAL: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 5(22) CRITICAL: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 5(22) CRITICAL: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 5(22) CRITICAL: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 5(22) CRITICAL: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 5(22) CRITICAL: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 5(22) CRITICAL: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 3(20) CRITICAL: <core> [core/parser/parse_fline.c:244]: parse_first_line(): parse_first_line: bad request first line

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 3(20) CRITICAL: <core> [core/parser/parse_fline.c:246]: parse_first_line(): at line 0 char 29:

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 3(20) CRITICAL: <core> [core/parser/parse_fline.c:252]: parse_first_line(): parsed so far: MEGACO/2 [175.15.0.254]:32791

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 3(20) CRITICAL: <core> [core/parser/parse_fline.c:257]: parse_first_line(): parse_first_line: bad message (offset: 29)

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 3(20) CRITICAL: <core> [core/parser/msg_parser.c:601]: parse_msg(): invalid message

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 3(20) CRITICAL: <core> [core/parser/msg_parser.c:676]: parse_msg(): ERROR: parse_msg: message=<MEGACO/2 [175.15.0.254]:32791

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: Transaction = 359 {

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal:        Context = - {

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal:                Notify = ROOT {

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal:                        ObservedEvents = 1111 {

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal:                                20180626T15175177:

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal:                                it/ito

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal:                        }

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal:                }

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal:        }

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: }>

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 3(20) CRITICAL: <core> [core/pvapi.c:1377]: pv_printf(): no more space for spec value

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 3(20) CRITICAL: <core> [core/pvapi.c:1386]: pv_printf(): buffer overflow -- increase the buffer size...

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 3(20) CRITICAL: nosip [megaco_capture.c:344]: megaco_capture(): Dump msg:[MEGACO/2 [175.15.0.254]:32791

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: Transaction = 359 {

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal:        Context = - {

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal:                Notify = ROOT {

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal:                        ObservedEvents = 1111 {

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal:                                20180626T15175177:

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal:                                it/ito

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal:                        }

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal:                }

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal:        }

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: }]#033[0;39;49m#033[0;33;49m 3(20) CRITICAL: nosip [megaco_capture.c:49]: megaco_error_code(): No error in MEGCO!

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 3(20) CRITICAL: nosip [megaco_capture.c:406]: megaco_capture(): No error code.#033[0;39;49m#033[0;33;49m 3(20) CRITICAL: nosip [megaco_capture.c:269]: megaco_capture_store(): az_megaco_tmstamp(1529997471897950)//debug log, this is the non-dup message.

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 3(20) CRITICAL: nosip [megaco_capture.c:305]: megaco_capture_store(): insert into homer table: [megaco_capture_all_20180626]

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 3(20) CRITICAL: nosip [megaco_capture.c:308]: megaco_capture_store(): storing info...

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 3(20) CRITICAL: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 3(20) CRITICAL: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 3(20) CRITICAL: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 3(20) CRITICAL: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)

Jun 26 07:17:51 dnt02-elk-control-worker-edge-01 journal: #033[0;39;49m#033[0;33;49m 3(20) CRITICAL: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)

Best Regards,

Alec Zhong