We are developing on and running Postgres 9.3.5 on FreeBsd 10.0-p12. We have been experiencing a intermittent postgres core dump which Seems primarily to be associated with the the 2 functions below. The area of interest is based on the content of the postgres log file which often indicates 2014-12-01T14:37:41.559787-05:00 puertorico local0 info postgres[30154]: [3-2] DETAIL: Failed process was running: SELECT * FROM cc.get_port_and_registration_data($1, $2, $3, $4, $5) 2014-12-01T14:37:41.559794-05:00 puertorico local0 info postgres[30154]: [4-1] LOG: terminating any other active server processes And that the core file back trace may show association to perl libraries of which we only have two possibilities currently, and this is the most relevant logic. Given the onset of this problem, we suspect it has something to do with the addition of DNS lookup within the our perlu function cc.get_sip_id(…). I would note that we have captured the details of the arguments to the cc.get_port_and_registration_data at time of a core and can repeat the same query after the core event without incident. Currently we are testing for an absence of the core event by commenting out dns perl function logic and have rebuilt postgres with debugging symbols. An example core of this output is below. ( prior to function alteration ). I am usually attempting to debug simpler program errors without such a bad impact on the postgres server. I would appreciate any comment on potential issues or bad practices in the suspect functions and/or additional details that could be gathered from the core files that might assist in resolving this matter. Thanks Dave Day CREATE OR REPLACE FUNCTION cc.get_port_and_registration_data(cca character varying, tgrp character varying, dhost character varying, usr character varying[], orig_flag boolean) RETURNS SETOF cc.port_type_tbl AS $BODY$ -- The inputs to this overloaded function are sip parameters. DECLARE pid INTEGER; DECLARE uid INTEGER; DECLARE mode CHARACTER VARYING; DECLARE sql_result record; BEGIN SELECT * FROM cc.get_sip_id($1,$2,$3, $4) INTO pid LIMIT 1; -- Perl invocation FOR sql_result IN SELECT cc.get_db_refhndl($5)AS db_ref_hndl,* FROM cc.port_info t1 LEFT JOIN (SELECT translator_id, mgcp_digit_map FROM cc.translator_sys) t2 USING (translator_id) LEFT JOIN cc.register_port USING (port_id) WHERE port_id = pid AND op_mode = 'default' ORDER by expiration DESC LOOP RETURN NEXT sql_result; END LOOP; RETURN; END; $BODY$ LANGUAGE plpgsql VOLATILE COST 100 ROWS 1000; ALTER FUNCTION cc.get_port_and_registration_data(character varying, character varying, character varying, character varying[], boolean) OWNER TO redcom; CREATE OR REPLACE FUNCTION cc.get_sip_id(cca character varying, tgrp character varying, dhost character varying, usr character varying[]) RETURNS integer AS $BODY$ use Socket qw(getaddrinfo getnameinfo PF_UNSPEC SOCK_STREAM AI_NUMERICHOST NI_NAMEREQD NIx_NOSERV); use URI; sub is_local { my $host = shift(@_); my $result = 0; open my $fh, "/sbin/route get $host |"; while (<$fh>) { if (m/interface/) { chomp; my @fields = split /\s+/; if ($fields[2] eq "lo0") { $result = 1; } last; } } close $fh; return $result; } my ($cca, $tgrp, $dhost, $usr) = @_; $do_dns_lookup = 1; { my $query = qq{ SELECT sip_dns_lookup_on_incoming_requests FROM admin.system_options; }; my $rv = spi_exec_query($query, 1); if ($rv->{status} =~ /^SPI_OK/ && $rv->{processed} > 0) { $do_dns_lookup = $rv->{rows}[0]->{sip_dns_lookup_on_incoming_requests}; } } if ($tgrp ne '') { my $query = qq{ SELECT port_id FROM cc.port_info WHERE destination_group_id = '$tgrp'; }; my $rv = spi_exec_query($query, 1); if ($rv->{status} =~ /^SPI_OK/ && $rv->{processed} > 0) { return $rv->{rows}[0]->{port_id}; } } if ($cca ne '') { my $query = qq{ SELECT port_id FROM cc.port_info WHERE call_control_agent = '$cca'; }; my $rv = spi_exec_query($query, 1); if ($rv->{status} =~ /^SPI_OK/ && $rv->{processed} > 0) { return $rv->{rows}[0]->{port_id}; } } for my $uristr (@$usr) { if ($uristr ne '') { my $uri = URI->new($uristr); if (is_local($uri->host)) { $dhost = ''; my $name = $uri->user; if ($name ne '') { my $query = qq{ SELECT port_id FROM cc.port_info WHERE registration_user = '$name'; }; my $rv = spi_exec_query($query, 1); if ($rv->{status} =~ /^SPI_OK/ && $rv->{processed} > 0) { return $rv->{rows}[0]->{port_id}; } } } } } if ($dhost ne '') { $pattern = "[:@]" . quotemeta($dhost) . "(?::\\\d+)?(?:;.*)?\$"; my $query = qq{ SELECT port_id FROM cc.port_info WHERE port_address ~* '$pattern'; }; my $rv = spi_exec_query($query, 1); if ($rv->{status} =~ /^SPI_OK/ && $rv->{processed} > 0) { return $rv->{rows}[0]->{port_id}; } if ($do_dns_lookup) { my %hints = (family => PF_UNSPEC, socktype => SOCK_STREAM, flags => AI_NUMERICHOST); $dhost_trimmed = ($dhost =~ m/\[(.*)\]/) ? $1 : $dhost; my ($err, @result) = getaddrinfo($dhost_trimmed, "", \%hints); if ($err == 0) { for my $ai (@result) { my ($err, $hostname) = getnameinfo($ai->{addr}, NI_NAMEREQD, NIx_NOSERV); if ($err == 0 && $hostname ne '') { $pattern = "[:@]" . quotemeta($hostname) . "(?::\\\d+)?(?:;.*)?\$"; my $query = qq{ SELECT port_id FROM cc.port_info WHERE port_address ~* '$pattern'; }; my $rv = spi_exec_query($query , 1); if ($rv->{status} =~ /^SPI_OK/ && $rv->{processed} > 0) { return $rv->{rows}[0]->{port_id}; } } } } } else { if ($dhost eq "127.0.0.1") { $pattern = "[:@]localhost(?::\\\d+)?(?:;.*)?\$"; my $query = qq{ SELECT port_id FROM cc.port_info WHERE port_address ~* '$pattern'; }; my $rv = spi_exec_query($query , 1); if ($rv->{status} =~ /^SPI_OK/ && $rv->{processed} > 0) { return $rv->{rows}[0]->{port_id}; } } } } for my $uristr (@$usr) { if ($uristr ne '') { my $uri = URI->new($uristr); my $name = $uri->user; if ($name ne '') { my $query = qq{ SELECT port_id FROM cc.port_info WHERE registration_user = '$name'; }; my $rv = spi_exec_query($query, 1); if ($rv->{status} =~ /^SPI_OK/ && $rv->{processed} > 0) { return $rv->{rows}[0]->{port_id}; } } } } return 0; $BODY$ LANGUAGE plperlu VOLATILE COST 100; ALTER FUNCTION cc.get_sip_id(character varying, character varying, character varying, character varying[]) OWNER TO redcom;
(gdb) bt full #0 0x00000000006f50b0 in spg_range_quad_picksplit (fcinfo=<optimized out>) at rangetypes_spgist.c:233 empty = 0 '\000' empty = 0 '\000' in = 0xf93a1 typcache = 0x0 i = <error reading variable i (Cannot access memory at address 0x0)> nonEmptyCount = <optimized out> centroid = <optimized out> #1 0x0000000000705681 in perform_relmap_update (updates=<optimized out>, shared=0 '\000') at relmapper.c:842 newmap = {magic = 7296347, num_mappings = 0, mappings = {{mapoid = 4294948304, mapfilenode = 32767}, {mapoid = 2679032113, mapfilenode = 0}, {mapoid = 4294948336, mapfilenode = 32767}, { mapoid = 7296186, mapfilenode = 0}, {mapoid = 0, mapfilenode = 0}, {mapoid = 43286576, mapfilenode = 8}, {mapoid = 4294948400, mapfilenode = 32767}, {mapoid = 0, mapfilenode = 0}, { mapoid = 4294948736, mapfilenode = 32767}, {mapoid = 7295065, mapfilenode = 0}, {mapoid = 4294967294, mapfilenode = 0}, {mapoid = 43297248, mapfilenode = 8}, {mapoid = 640, mapfilenode = 0}, {mapoid = 43297240, mapfilenode = 8}, {mapoid = 4088945280, mapfilenode = 0}, {mapoid = 218805760, mapfilenode = 8}, {mapoid = 0, mapfilenode = 196609}, { mapoid = 0, mapfilenode = 0}, {mapoid = 6913104, mapfilenode = 0}, {mapoid = 184, mapfilenode = 65538}, {mapoid = 2, mapfilenode = 0}, {mapoid = 0, mapfilenode = 0}, { mapoid = 42547296, mapfilenode = 8}, {mapoid = 0, mapfilenode = 0}, {mapoid = 1020833, mapfilenode = 0}, {mapoid = 0, mapfilenode = 196610}, {mapoid = 0, mapfilenode = 0}, { mapoid = 6824176, mapfilenode = 0}, {mapoid = 63, mapfilenode = 65538}, {mapoid = 2, mapfilenode = 0}, {mapoid = 0, mapfilenode = 0}, {mapoid = 42547296, mapfilenode = 8}, { mapoid = 0, mapfilenode = 0}, {mapoid = 15, mapfilenode = 0}, {mapoid = 0, mapfilenode = 196611}, {mapoid = 0, mapfilenode = 0}, {mapoid = 6698992, mapfilenode = 0}, {mapoid = 60, mapfilenode = 65538}, {mapoid = 2, mapfilenode = 0}, {mapoid = 0, mapfilenode = 0}, {mapoid = 42547296, mapfilenode = 8}, {mapoid = 0, mapfilenode = 0} <repeats 11 times>, { mapoid = 4294967295, mapfilenode = 0}, {mapoid = 218817224, mapfilenode = 8}, {mapoid = 218805768, mapfilenode = 8}, {mapoid = 22, mapfilenode = 0}, {mapoid = 15, mapfilenode = 0}, { mapoid = 1020833, mapfilenode = 0}, {mapoid = 4294948784, mapfilenode = 32767}, {mapoid = 7362177, mapfilenode = 0}, {mapoid = 0, mapfilenode = 0}, {mapoid = 218817224,mapfilenode = 8}}, crc = 226, pad = 0} #2 AtEOXact_RelationMap (isCommit=<optimized out>) at relmapper.c:423 No locals. #3 0x00000000005c3fe0 in cost_merge_append (path=0x80d0ae318, root=0xda8e0956, pathkeys=0xe02190c4, n_streams=<optimized out>, input_startup_cost=6.9533558069622868e-310, input_total_cost=1.7084015800703071e-313, tuples=6.9533558069255283e-310) at costsize.c:1383 run_cost = <optimized out> startup_cost = <optimized out> N = 1.6996756523143625e-313 comparison_cost = <optimized out> logN = <optimized out> #4 0x00000000005c3f30 in cost_sort (path=0xf, root=0xda8e0956, pathkeys=0xe02190c4, input_cost=<optimized out>, tuples=<optimized out>, width=<optimized out>, comparison_cost=<optimized out>, sort_mem=<optimized out>, limit_tuples=<optimized out>) at costsize.c:1303 mergeorder = 0 npageaccesses = <optimized out> nruns = <optimized out> startup_cost = 1.6996987484999217e-313 run_cost = <optimized out> input_bytes = <optimized out> output_bytes = <optimized out> sort_mem_bytes = <optimized out> #5 0x00000000005bf6d3 in remove_gene (root=<optimized out>, gene=<optimized out>, edge=..., edge_table=<optimized out>) at geqo_erx.c:257 possess_edge = <optimized out> genes_remaining = -534671164 #6 gimme_tour (root=0x7fffffffbb00, edge_table=0x16, new_gene=0x100000001, num_gene=1020833) at geqo_erx.c:208 edge_failures = <error reading variable edge_failures (Cannot access memory at address 0x0)> #7 0x00000000005be515 in copyParamList (from=0x1) at params.c:69 typLen = 0 typLen = 0 oprm = 0x80294a9d8 typByVal = 127 '\177' typByVal = 127 '\177' nprm = 0x80d0903a8 size = <optimized out> retval = 0x80d0903a8 i = <error reading variable i (Cannot access memory at address 0x0)> #8 0x00000000005d6d1e in create_lateral_join_info (root=0x80d0abd58) at initsplan.c:547 brel = 0x7 lateral_referencers = <optimized out> lc = <optimized out> rti = <optimized out> #9 0x00000000005d8b83 in query_planner (root=0x0, tlist=0x802ba2120, tuple_fraction=3.0451286481687515e-317, limit_tuples=0, qp_callback=0x7fffffffbbd0, qp_extra=0x80d0ab2f0, cheapest_path=0x80d0ab390, sorted_path=0x80d0ab358, num_groups=<optimized out>) at planmain.c:128 parse = 0x80d090718 joinlist = <optimized out> total_pages = <optimized out> final_rel = <optimized out> cheapestpath = <optimized out> sortedpath = <optimized out> #10 0x00000000005d7c54 in distribute_qual_to_rels (root=0x80d0903a8, clause=0x802ba2120, is_deduced=0 '\000', below_outer_join=8 '\b', jointype=8, qualscope=0x802ba2120, ojscope=0x0, outerjoin_nonnullable=<optimized out>, deduced_nullable_relids=<optimized out>, postponed_qual_list=<optimized out>) at initsplan.c:1379 relids = 0x802a00a68 nullable_relids = 0x60 relids = 0x802a00a68 relids = 0x802a00a68 relids = 0x802a00a68 relids = 0x802a00a68 relids = 0x802a00a68 nullable_relids = 0x60 pseudoconstant = <error reading variable pseudoconstant (Cannot access memory at address 0x0)> maybe_equivalence = <optimized out> outerjoin_delayed = <optimized out> restrictinfo = <optimized out> #11 0x00000000005d705b in deconstruct_recurse (root=0x802a00a68, jtnode=0x0, below_outer_join=8 '\b', qualscope=0x0, inner_join_rels=0x802a00a68, postponed_qual_list=0x60) at initsplan.c:744 sub_qualscope = 0x802ba2120 sub_qualscope = 0x802ba2120 sub_joinlist = 0x802a00a68 sub_members = <optimized out> child_postponed_quals = 0x802b96080 l = <optimized out> joinlist = <optimized out> #12 0x000000000063ebed in mdtruncate (reln=<optimized out>, forknum=32767, nblocks=0) at md.c:921 lastsegblocks = <optimized out> ov = <optimized out> curnblk = <optimized out> v = <optimized out> #13 0x000000000063ecab in mdpostckpt () at md.c:1287 absorb_counter = <optimized out> #14 0x00000000006f88b5 in SearchCatCache (cache=0x63ebed <mdtruncate+461>, v1=<optimized out>, v2=<optimized out>, v3=<optimized out>, v4=140737488338336) at catcache.c:1117 __atp = <optimized out> __test = <optimized out> __isnull = 0 '\000' __isnull = 0 '\000' __isnull = 0 '\000' __cur_keys = 0x802ba2120 __cur_nkeys = <optimized out> cur_skey = {{sk_flags = 45752608, sk_attno = 8, sk_strategy = 0, sk_subtype = 218892072, sk_collation = 8, sk_func = {fn_addr = 0x60, fn_oid = 96, fn_nargs = 0, fn_strict = 0 '\000', fn_retset = 0 '\000', fn_stats = 104 'h', fn_extra = 0x0, fn_mcxt = 0x802a00a68, fn_expr = 0x0}, sk_argument = 34403781224}, {sk_flags = 218694424, sk_attno = 8, sk_strategy = 0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr = 0x0, fn_oid = 4294950464, fn_nargs = 32767, fn_strict = 0 '\000', fn_retset = 0 '\000', fn_stats = 91 '[', fn_extra = 0x802b96830, fn_mcxt = 0x802ba2120, fn_expr = 0x802b96080}, sk_argument = 0}, {sk_flags = 45752608, sk_attno = 8, sk_strategy = 0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr = 0x802a00a68, fn_oid = 0, fn_nargs = 0, fn_strict = 0 '\000', fn_retset = 0 '\000', fn_stats = 112 'p', fn_extra = 0x63ebed <mdtruncate+461>, fn_mcxt = 0x802ba2030, fn_expr = 0x0}, sk_argument = 34403781224}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 4294950560, sk_collation = 32767, sk_func = {fn_addr = 0x63ecab <mdpostckpt+11>, fn_oid = 45752432, fn_nargs = 8, fn_strict = 0 '\000', fn_retset = 0 '\000', fn_stats = 0 '\000', fn_extra = 0x802a00a68, fn_mcxt = 0x802b94830, fn_expr = 0x7fffffffbee0}, sk_argument = 7309493}} hashValue = 4294950304 hashIndex = 218892072 bucket = 0x802b94830 relation = <optimized out> scandesc = <optimized out> ntp = <optimized out> ct = <optimized out> #15 0x00000000006f835f in InitCatCache (id=-19952, reloid=3666741590, indexoid=3760296132, nkeys=43297240, key=0x7ff7fd6b3590, nbuckets=218838980) at catcache.c:730 oldcxt = 0x802a00a68 #16 0x000000000059329c in _SPI_execute_plan (plan=0x802b94800, paramLI=0x802b94830, snapshot=<optimized out>, crosscheck_snapshot=0x802a00a01, read_only=0 '\000', fire_triggers=<optimized out>, tcount=<optimized out>) at spi.c:2194 completionTag = "\240\277\377\377\377\177\000\000\234\062Y\000\000\000\000\000\060l\271\002\b\000\000\000\060H\271\002\b\000\000\000x\v\240\002\000\000\000\000h\n\240\002\b\000\000\000p\302 \377\377\377\177\000\000@=Y\000\000\000\000" canSetTag = <optimized out> dest = <optimized out> stmt_list = <optimized out> lc2 = <optimized out> spierrcontext = {previous = 0x8029f7140, callback = 0x80bc09448, arg = 0x802a00a68} spierrcontext = {previous = 0x8029f7140, callback = 0x80bc09448, arg = 0x802a00a68}my_res = <error reading variable my_res (Cannot access memory at address 0xe)> my_processed = <error reading variable my_processed (Cannot access memory at address 0x0)> my_lastoid = <error reading variable my_lastoid (Cannot access memory at address 0x0)> res = <error reading variable res (Cannot access memory at address 0x0)> pushed_active_snap = <error reading variable pushed_active_snap (Cannot access memory at address 0x0)> my_tuptable = <optimized out> cplan = 0x0 lc1 = <optimized out> #17 0x000000080b9078c5 in ?? () No symbol table info available. #18 0x000000080b9083d0 in ?? () No symbol table info available. #19 0x000000080bc09a00 in ?? () No symbol table info available. #20 0x00007fffffffc288 in ?? () No symbol table info available. #21 0x000000080bc09a70 in ?? () No symbol table info available. #22 0x000000080bc098f8 in ?? () No symbol table info available. #23 0x00007fffffffc288 in ?? () No symbol table info available. #24 0x00007fffffffc150 in ?? () No symbol table info available. #25 0x000000080b9083e5 in ?? () No symbol table info available. #26 0x0000000000000000 in ?? () No symbol table info available. |
