[SR-Users] [Kamailio]: Parse and Store nosip Message error.

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