Hello,
I assume that the insert into the database is done from your new module.
For us, it is hard to troubleshoot what happens there, not having the
code. If you do the database insert via some kamailio.cfg scripting
using existing modules, then attach it here and we will try to spot if
something is wrong there.
Cheers,
Daniel
On 02.07.18 04:11, Zhong, Alec (NSB - CN/Qingdao) wrote:
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
_______________________________________________
Kamailio (SER) - Users Mailing List
sr-users(a)lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
--
Daniel-Constantin Mierla --
www.asipto.com
www.twitter.com/miconda --
www.linkedin.com/in/miconda
Kamailio World Conference --
www.kamailioworld.com