[SR-Users] [Kamailio]: Parse and Store nosip Message error.
Daniel-Constantin Mierla
miconda at gmail.com
Tue Jul 3 13:07:41 CEST 2018
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 at 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20180703/f9ee047b/attachment.html>
More information about the sr-users
mailing list