Thread: Trouble with plpgsql on 7.4.6
Has anyone else had any problem installing plpgsql into a 7.4.6 database? When I try (on NetBSD 2.0RC5) I get the following message: createlang: language installation failed: server closed the connection unexpectedly This does not happen on 7.4.3, the other system that I have installed. It doesn't happen if I use 7.4.6 to access a database built by 7.4.3. It happens on 7.4.6 if I initdb a new database and simply run the createlang command against it. Here is a test script which I ran in a scratch directory. initdb . pg_ctl -D . start sleep 3 createlang plpgsql template1 The closest thing I could find in the archives is the message about 7.4.5 in http://archives.postgresql.org/pgsql-hackers/2004-09/msg00915.php. I don't think there is a connection but I could be wrong. I turned on a bunch of logging and this is what gets spit out into the log: Nov 18 11:49:18 panther cert198[21983]: [47-1] LOG: 00000: server process (PID 7864) was terminated by signal 6 Nov 18 11:49:18 panther cert198[21983]: [47-2] LOCATION: LogChildExit, postmaster.c:2087 Nov 18 11:49:18 panther cert198[21983]: [48-1] LOG: 00000: terminating any other active server processes Nov 18 11:49:18 panther cert198[21983]: [48-2] LOCATION: CleanupProc, postmaster.c:2008 Nov 18 11:49:18 panther cert198[21983]: [49-1] LOG: 00000: all server processes terminated; reinitializing Nov 18 11:49:18 panther cert198[21983]: [49-2] LOCATION: reaper, postmaster.c:1920 Nov 18 11:49:18 panther cert198[1332]: [52-1] LOG: 00000: database system was interrupted at 2004-11-18 11:43:53 EST Nov 18 11:49:18 panther cert198[1332]: [52-2] LOCATION: StartupXLOG, xlog.c:2610 Nov 18 11:49:18 panther cert198[1332]: [53-1] LOG: 00000: checkpoint record is at 0/9F5B40 Nov 18 11:49:18 panther cert198[1332]: [53-2] LOCATION: StartupXLOG, xlog.c:2628 Nov 18 11:49:18 panther cert198[1332]: [54-1] LOG: 00000: redo record is at 0/9F5B40; undo record is at 0/0; shutdown TRUE Nov 18 11:49:18 panther cert198[1332]: [54-2] LOCATION: StartupXLOG, xlog.c:2653 Nov 18 11:49:18 panther cert198[1332]: [55-1] LOG: 00000: next transaction ID: 574; next OID: 74486 Nov 18 11:49:18 panther cert198[1332]: [55-2] LOCATION: StartupXLOG, xlog.c:2656 Nov 18 11:49:18 panther cert198[1332]: [56-1] LOG: 00000: database system was not properly shut down; automatic recovery in progress Nov 18 11:49:18 panther cert198[1332]: [56-2] LOCATION: StartupXLOG, xlog.c:2705 Nov 18 11:49:19 panther cert198[1332]: [57-1] LOG: 00000: redo starts at 0/9F5B80 Nov 18 11:49:19 panther cert198[1332]: [57-2] LOCATION: StartupXLOG, xlog.c:2733 Nov 18 11:49:19 panther cert198[1332]: [58-1] LOG: 00000: invalid magic number 0000 in log file 0, segment 0, offset 10477568 Nov 18 11:49:19 panther cert198[1332]: [58-2] LOCATION: ValidXLOGHeader, xlog.c:2048 Nov 18 11:49:19 panther cert198[1332]: [59-1] LOG: 00000: redo done at 0/9FBCAC Nov 18 11:49:19 panther cert198[1332]: [59-2] LOCATION: StartupXLOG, xlog.c:2765 Nov 18 11:49:21 panther cert198[1332]: [60-1] LOG: 00000: database system is ready Nov 18 11:49:21 panther cert198[1332]: [60-2] LOCATION: StartupXLOG, xlog.c:2946 -- D'Arcy J.M. Cain <darcy@druid.net> | Democracy is three wolves http://www.druid.net/darcy/ | and a sheep voting on +1 416 425 1212 (DoD#0082) (eNTP) | what's for dinner.
"D'Arcy J.M. Cain" <darcy@druid.net> writes:
> Has anyone else had any problem installing plpgsql into a 7.4.6
> database? When I try (on NetBSD 2.0RC5) I get the following message:
> createlang: language installation failed: server closed the connection
> unexpectedly
Probably indicates a failure to load the plpgsql shared library.
> I turned on a bunch of logging and this is what gets spit out into the
> log:
> Nov 18 11:49:18 panther cert198[21983]: [47-1] LOG: 00000: server
> process (PID 7864) was terminated by signal 6
There wasn't anything interesting just before that?
Signal 6 is SIGABRT (at least on my machine) so something decided to
abort() in that backend. Postgres would abort() on assertion failure,
but it would have logged a message first. My guess is that the shared
library loader did the abort(), and probably it griped on stderr rather
than to syslog. Fix your postmaster startup arrangement so that stderr
goes someplace useful instead of to /dev/null, so you can see what it's
complaining about.
regards, tom lane
On Thu, 18 Nov 2004 14:25:41 -0500
Tom Lane <tgl@sss.pgh.pa.us> wrote:
> "D'Arcy J.M. Cain" <darcy@druid.net> writes:
> > Has anyone else had any problem installing plpgsql into a 7.4.6
> > database? When I try (on NetBSD 2.0RC5) I get the following
> > message:
>
> > createlang: language installation failed: server closed the
> > connection unexpectedly
>
> Probably indicates a failure to load the plpgsql shared library.
I considered that but the file is where I expect it to be. I did this:
[pgsql@panther:/data/cert198] $ pg_config --libdir
/usr/pkg/lib
The file is actually in /usr/pkg/lib/postgresql/plpgsql.so. I wasn't
sure if the postgresql was added so I made a symlink to assure that it
was available in both. locations.
> > I turned on a bunch of logging and this is what gets spit out into
> > the log:
>
> > Nov 18 11:49:18 panther cert198[21983]: [47-1] LOG: 00000: server
> > process (PID 7864) was terminated by signal 6
>
> There wasn't anything interesting just before that?
Not that I can see. I have attached the entire output of the capture
from the start. Here are the diffs from the postgresql.conf created by
initdb.
--- postgresql.conf.orig 2004-11-18 15:33:03.000000000 -0500
+++ postgresql.conf 2004-11-18 15:33:17.000000000 -0500
@@ -136,24 +136,24 @@
# - Syslog -
-#syslog = 0 # range 0-2; 0=stdout; 1=both; 2=syslog
-#syslog_facility = 'LOCAL0'
-#syslog_ident = 'postgres'
+syslog = 1 # range 0-2; 0=stdout; 1=both; 2=syslog
+syslog_facility = 'LOCAL4'
+syslog_ident = 'postgres'
# - When to Log -
-#client_min_messages = notice # Values, in order of decreasing detail:
+client_min_messages = debug5 # Values, in order of decreasing detail:
# debug5, debug4, debug3, debug2,
debug1,
# log, info, notice, warning, error
-#log_min_messages = notice # Values, in order of decreasing detail:
+log_min_messages = debug5 # Values, in order of decreasing detail:
# debug5, debug4, debug3, debug2,
debug1,
# info, notice, warning, error, log,
fatal,
# panic
-#log_error_verbosity = default # terse, default, or verbose messages
+log_error_verbosity = verbose # terse, default, or verbose messages
-#log_min_error_statement = panic # Values in order of increasing
severity:
+log_min_error_statement = debug5 # Values in order of increasing
severity:
# debug5, debug4, debug3, debug2,
debug1,
# info, notice, warning, error,
panic(off)
@@ -162,7 +162,7 @@
# milliseconds. Zero prints all
queries.
# Minus-one disables.
-#silent_mode = false # DO NOT USE without Syslog!
+silent_mode = false # DO NOT USE without Syslog!
# - What to Log -
@@ -170,11 +170,11 @@
#debug_print_rewritten = false
#debug_print_plan = false
#debug_pretty_print = false
-#log_connections = false
-#log_duration = false
-#log_pid = false
-#log_statement = false
-#log_timestamp = false
+log_connections = true
+log_duration = true
+log_pid = true
+log_statement = true
+log_timestamp = true
#log_hostname = false
#log_source_port = false
> Signal 6 is SIGABRT (at least on my machine) so something decided to
Same on mine.
Thanks for the help.
--
D'Arcy J.M. Cain <darcy@druid.net> | Democracy is three wolves
http://www.druid.net/darcy/ | and a sheep voting on
+1 416 425 1212 (DoD#0082) (eNTP) | what's for dinner.
Attachment
"D'Arcy J.M. Cain" <darcy@druid.net> writes:
> I thought that this would have sent everything to both the log and the
> screen but I found that the syslog has much more detail. I have
> attached that output.
We still need to look at the stderr output. All this says is that
you're getting repeated abort()s. It's unlikely that anything would
be coded to abort() without emitting any gripe at all --- but the gripe
is not appearing in syslog output, so stderr is the next place to look.
Also see about getting a stack trace from one of the core dumps.
regards, tom lane
On Sat, 20 Nov 2004 11:17:48 -0500
Tom Lane <tgl@sss.pgh.pa.us> wrote:
> "D'Arcy J.M. Cain" <darcy@druid.net> writes:
> > I thought that this would have sent everything to both the log and
> > the screen but I found that the syslog has much more detail. I have
> > attached that output.
>
> We still need to look at the stderr output. All this says is that
> you're getting repeated abort()s. It's unlikely that anything would
> be coded to abort() without emitting any gripe at all --- but the
> gripe is not appearing in syslog output, so stderr is the next place
> to look.
The stderr was in the previous message. No gripes there either other
than in the startup after the failure.
> Also see about getting a stack trace from one of the core dumps.
I did look at the core file and here is what I saw:
#0 0x483cafeb in kill () from /usr/lib/libc.so.12
#1 0x483cd0af in __libc_mutex_catchall_stub (m=1212478892) at /usr/src/lib/libc/thread-stub/thread-stub.c:112
#2 0x4843f0f7 in free (ptr=<incomplete type>) at /usr/src/lib/libc/stdlib/malloc.c:1149
#3 0x081b3efc in AllocSetDelete (context=<error type>) at aset.c:464
#4 0x081b468a in MemoryContextDelete (context=<error type>) at
#mcxt.c:192
In fact it is calling the thread stubs but the applicatino is threaded.
At least, that's what I see from this code in NetBSD.
#define CHECK_NOT_THREADED_ALWAYS() \
do { \ if (__isthreaded) \ DIE(); \
} while (/*CONSTCOND*/0)
#if 1
#define CHECK_NOT_THREADED() CHECK_NOT_THREADED_ALWAYS()
#else
#define CHECK_NOT_THREADED() /* nothing */
#endif
I am going to follow up with the NetBSD team but I pass this on in case
it suggests anything. Note that this still only causes problems on
7.4.6 and not under 7.4.3.
--
D'Arcy J.M. Cain <darcy@druid.net> | Democracy is three wolves
http://www.druid.net/darcy/ | and a sheep voting on
+1 416 425 1212 (DoD#0082) (eNTP) | what's for dinner.
On Tue, Nov 23, 2004 at 07:25:17AM -0500, D'Arcy J.M. Cain wrote:
> The stderr was in the previous message. No gripes there either other
> than in the startup after the failure.
>
> > Also see about getting a stack trace from one of the core dumps.
>
> I did look at the core file and here is what I saw:
>
> #0 0x483cafeb in kill () from /usr/lib/libc.so.12
> #1 0x483cd0af in __libc_mutex_catchall_stub (m=1212478892)
> at /usr/src/lib/libc/thread-stub/thread-stub.c:112
> #2 0x4843f0f7 in free (ptr=<incomplete type>)
> at /usr/src/lib/libc/stdlib/malloc.c:1149
> #3 0x081b3efc in AllocSetDelete (context=<error type>) at aset.c:464
> #4 0x081b468a in MemoryContextDelete (context=<error type>) at
> #mcxt.c:192
Would setting the following environment variable get you an earlier
abort / more logging? (pthread(3))
PTHREAD_DIAGASSERT Possible values are any combinations of: A
Ignoreerrors. a Abort on errors, creating a core
dump for further debugging. E Do not log errors to stdout.
e Log errors to stdout. L Do not log
errorsvia syslogd(8). l Log
errorsvia syslogd(8).
Cheers,
Patrick
On Tue, 23 Nov 2004 07:25:17 -0500
"D'Arcy J.M. Cain" <darcy@druid.net> wrote:
>
> #0 0x483cafeb in kill () from /usr/lib/libc.so.12
> #1 0x483cd0af in __libc_mutex_catchall_stub (m=1212478892)
> at /usr/src/lib/libc/thread-stub/thread-stub.c:112
> #2 0x4843f0f7 in free (ptr=<incomplete type>)
> at /usr/src/lib/libc/stdlib/malloc.c:1149
> #3 0x081b3efc in AllocSetDelete (context=<error type>) at aset.c:464
> #4 0x081b468a in MemoryContextDelete (context=<error type>) at
> #mcxt.c:192
>
> In fact it is calling the thread stubs but the applicatino is
> threaded. At least, that's what I see from this code in NetBSD.
>
> #define CHECK_NOT_THREADED_ALWAYS() \
> do { \
> if (__isthreaded) \
> DIE(); \
> } while (/*CONSTCOND*/0)
>
> #if 1
> #define CHECK_NOT_THREADED() CHECK_NOT_THREADED_ALWAYS()
> #else
> #define CHECK_NOT_THREADED() /* nothing */
> #endif
>
> I am going to follow up with the NetBSD team but I pass this on in
> case it suggests anything. Note that this still only causes problems
> on 7.4.6 and not under 7.4.3.
OK, I have found the problem. It turns out to be in the way that it is
built under the NetBSD pkgsrc system. As soon as a module is loaded
that uses pthreads it sets a variable (__isthreaded) that causes the
above error. The answer is to simply link PostgreSQL with -lpthread to
begin with. We are making some changes to the pkgsrc system to do this
correctly with this and some other packages that could potentially have
the same problem.
Thanks for the help in finding this.
--
D'Arcy J.M. Cain <darcy@druid.net> | Democracy is three wolves
http://www.druid.net/darcy/ | and a sheep voting on
+1 416 425 1212 (DoD#0082) (eNTP) | what's for dinner.