Broken pipe errors using guile-pg with guile 1.8

Broken pipe errors using guile-pg with guile 1.8

[Sebastian Tennant]

[-- Attachment #1: Type: text/plain, Size: 1126 bytes --]

Hi Guilers,

Is anyone familiar with the internals of guile-pg (version 0.16, author
Ian Grant) which wraps PostgreSQL's libpq?

I'm getting a lot of 'broken pipe' errors of the sort:

 Feb 23 11:32:13 stderr: ERROR: In procedure pg-connectdb:
 Feb 23 11:32:13 stderr: ERROR: could not send startup packet: Broken pipe

It's especially bad at times of light load (rather than no load) and I
never once noticed this error whilst the webapp was in development
(i.e., I was the only person using it) which suggests to me that it's
happening whenever two or more page requests call scripts that attempt
to open database connections more or less at the same time.

All my calls to pg-connectdb are let bound so database connections are
(supposed to be) closed after every query.

Any advice very much appreciated.  I've attached a log extract to give
you an idea of the frequency of failures.  I need to find a solution to
this problem fast!

Seb

P.S. Perhaps upgrading guile-pg is the first thing I should try? IIRC
     there's a more recent pkgsrc version (which is guile 1.8
     comaptible) somewhere... hunting for it now.


[-- Attachment #2: broken_pipes.txt --]
[-- Type: text/plain, Size: 9277 bytes --]

Feb 23 11:32:12 session.scm: Called... 
Feb 23 11:32:12 session.scm: Called... 
Feb 23 11:32:13 stderr: ERROR: In procedure pg-connectdb:
Feb 23 11:32:13 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 11:32:13 home: home.scm: EXITED WITH CODE 1
Feb 23 11:32:13 listing-view: listing-view.scm: exited cleanly
Feb 23 11:32:13 listing-view: #
--
Feb 23 11:43:27 home: calling home.scm...
Feb 23 11:43:27 session.scm: Called... 
Feb 23 11:43:27 stderr: ERROR: In procedure pg-connectdb:
Feb 23 11:43:27 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 11:43:27 home: home.scm: EXITED WITH CODE 1
Feb 23 11:43:27 home: #
Feb 23 11:43:40 listing-view: calling listing-view.scm...
Feb 23 11:43:40 session.scm: Called... 
Feb 23 11:43:40 session.scm: User peteksirin has just logged in. 
Feb 23 11:43:40 stderr: ERROR: In procedure pg-connectdb:
Feb 23 11:43:40 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 11:43:40 listing-view: listing-view.scm: EXITED WITH CODE 1
Feb 23 11:43:40 listing-view: #
Feb 23 11:43:44 listing-view: calling listing-view.scm...
--
Feb 23 11:44:13 session.scm: Called... 
Feb 23 11:44:13 session.scm: User peteksirin has just logged in. 
Feb 23 11:44:13 stderr: ERROR: In procedure pg-connectdb:
Feb 23 11:44:13 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 11:44:13 listing-view: listing-view.scm: EXITED WITH CODE 1
Feb 23 11:44:14 listing-view: #
Feb 23 11:44:16 listing-view: calling listing-view.scm...
--
Feb 23 11:44:30 account-remind-form-handler.scm: Called... 
Feb 23 11:44:30 account-remind-form-handler.scm: Form checks passed. 
Feb 23 11:44:30 stderr: ERROR: In procedure pg-connectdb:
Feb 23 11:44:30 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 11:44:30 account-remind: account-remind.scm: EXITED WITH CODE 1
Feb 23 11:44:30 account-remind-form-handler.scm: Address is in use, account details exist.  Sending reminder... 
Feb 23 11:44:30 account-remind: #
--
Feb 23 11:45:37 account-remind: calling account-remind.scm...
Feb 23 11:45:37 session.scm: Called... 
Feb 23 11:45:37 stderr: ERROR: In procedure pg-connectdb:
Feb 23 11:45:37 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 11:45:37 account-remind-form-handler.scm: Called... 
Feb 23 11:45:37 account-remind-form-handler.scm: Form checks passed. 
Feb 23 11:45:37 account-remind-form-handler.scm: Address is in use, account details exist.  Sending reminder... 
--
Feb 23 11:46:10 home: calling home.scm...
Feb 23 11:46:10 session.scm: Called... 
Feb 23 11:46:10 stderr: ERROR: In procedure pg-connectdb:
Feb 23 11:46:10 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 11:46:10 home: home.scm: EXITED WITH CODE 1
Feb 23 11:46:10 home: #
Feb 23 11:46:12 listing-view: calling listing-view.scm...
--
Feb 23 11:46:19 home: calling home.scm...
Feb 23 11:46:19 session.scm: Called... 
Feb 23 11:46:19 stderr: ERROR: In procedure pg-connectdb:
Feb 23 11:46:19 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 11:46:19 home: home.scm: EXITED WITH CODE 1
Feb 23 11:46:19 home: #
Feb 23 11:46:25 listing-view: calling listing-view.scm...
--
Feb 23 11:47:22 session.scm: User peteksirin is logged in. 
Feb 23 11:47:22 session.scm: Called... 
Feb 23 11:47:22 stderr: ERROR: In procedure pg-connectdb:
Feb 23 11:47:22 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 11:47:22 listing-browse: listing-browse.scm: EXITED WITH CODE 1
Feb 23 11:47:23 listing-view: listing-view.scm: exited cleanly
Feb 23 11:47:23 listing-view: #
--
Feb 23 11:47:45 session.scm: Called... 
Feb 23 11:47:45 session.scm: User peteksirin is logged in. 
Feb 23 11:47:45 stderr: ERROR: In procedure pg-connectdb:
Feb 23 11:47:45 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 11:47:45 home: home.scm: EXITED WITH CODE 1
Feb 23 11:47:45 rates-rationale: rates-rationale.scm: exited cleanly
Feb 23 11:47:45 rates-rationale: #
--
Feb 23 11:48:40 home: calling home.scm...
Feb 23 11:48:40 session.scm: Called... 
Feb 23 11:48:40 stderr: ERROR: In procedure pg-connectdb:
Feb 23 11:48:40 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 11:48:40 home: home.scm: EXITED WITH CODE 1
Feb 23 11:48:40 home: #
Feb 23 11:48:52 listing-browse: calling listing-browse.scm...
--
Feb 23 11:49:52 home: calling home.scm...
Feb 23 11:49:52 session.scm: Called... 
Feb 23 11:49:52 stderr: ERROR: In procedure pg-connectdb:
Feb 23 11:49:52 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 11:49:52 home: home.scm: EXITED WITH CODE 1
Feb 23 11:49:52 home: #
Feb 23 11:50:11 home: calling home.scm...
Feb 23 11:50:11 session.scm: Called... 
Feb 23 11:50:11 stderr: ERROR: In procedure pg-connectdb:
Feb 23 11:50:11 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 11:50:11 home: home.scm: EXITED WITH CODE 1
Feb 23 11:50:11 home: #
Feb 23 11:50:29 listing-browse: calling listing-browse.scm...
Feb 23 11:50:29 session.scm: Called... 
Feb 23 11:50:30 stderr: ERROR: In procedure pg-connectdb:
Feb 23 11:50:30 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 11:50:30 listing-browse: listing-browse.scm: EXITED WITH CODE 1
Feb 23 11:50:30 listing-browse: #
Feb 23 11:50:46 listing-view: calling listing-view.scm...
--
Feb 23 11:51:13 home: calling home.scm...
Feb 23 11:51:14 session.scm: Called... 
Feb 23 11:51:14 stderr: ERROR: In procedure pg-connectdb:
Feb 23 11:51:14 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 11:51:14 home: home.scm: EXITED WITH CODE 1
Feb 23 11:51:14 home: #
Feb 23 11:51:26 listing-view: calling listing-view.scm...
--
Feb 23 11:52:20 home: calling home.scm...
Feb 23 11:52:20 session.scm: Called... 
Feb 23 11:52:20 stderr: ERROR: In procedure pg-connectdb:
Feb 23 11:52:20 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 11:52:20 home: home.scm: EXITED WITH CODE 1
Feb 23 11:52:21 home: #
Feb 23 11:53:08 home: calling home.scm...
Feb 23 11:53:08 session.scm: Called... 
Feb 23 11:53:08 stderr: ERROR: In procedure pg-connectdb:
Feb 23 11:53:08 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 11:53:08 home: home.scm: EXITED WITH CODE 1
Feb 23 11:53:08 home: #
Feb 23 11:54:23 listing-view: calling listing-view.scm...
--
Feb 23 11:57:50 stderr:   35: 3* [pg-connectdb "dbname=itidb"]
Feb 23 11:57:50 stderr: 
Feb 23 11:57:50 stderr: zlib/listing-pgutils.scm:35:18: In procedure pg-connectdb in expression (pg-connectdb "dbname=itidb"):
Feb 23 11:57:50 stderr: zlib/listing-pgutils.scm:35:18: could not send startup packet: Broken pipe
Feb 23 11:57:50 stderr: ABORT: (misc-error)
Feb 23 11:58:21 stderr: 
Feb 23 11:58:21 stderr: In standard input:
--
Feb 23 12:09:16 account-create-submission-handler.scm: Empty value checks passed and chosen username not in use. 
Feb 23 12:09:16 account-create-submission-handler.scm: Email address xxx@xxx.xxx in use, but without a username.  Performing sql UPDATE... 
Feb 23 12:09:16 stderr: ERROR: In procedure pg-connectdb:
Feb 23 12:09:16 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 12:09:16 account-create: account-create.scm: EXITED WITH CODE 1
Feb 23 12:09:16 account-create-submission-handler.scm: Done. 
Feb 23 12:09:17 account-create: #
--
Feb 23 12:13:07 account-create-submission-handler.scm: Called... 
Feb 23 12:13:07 account-create-submission-handler.scm: Empty value checks passed and chosen username not in use. 
Feb 23 12:13:07 stderr: ERROR: In procedure pg-connectdb:
Feb 23 12:13:07 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 12:13:07 account-create: account-create.scm: EXITED WITH CODE 1
Feb 23 12:13:07 account-create-submission-handler.scm: Email address xxx@xxx.xxx not in use.  Performing sql INSERT... 
Feb 23 12:13:08 account-create: #
--
Feb 23 15:52:26 home: calling home.scm...
Feb 23 15:52:26 session.scm: Called... 
Feb 23 15:52:26 stderr: ERROR: In procedure pg-connectdb:
Feb 23 15:52:26 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 15:52:26 home: home.scm: EXITED WITH CODE 1
Feb 23 15:52:26 home: #
Feb 23 15:53:33 listing-view: calling listing-view.scm...
--
Feb 23 16:09:35 session.scm: Called... 
Feb 23 16:09:35 account-create-submission-handler.scm: Called... 
Feb 23 16:09:35 stderr: ERROR: In procedure pg-connectdb:
Feb 23 16:09:35 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 16:09:35 account-create: account-create.scm: EXITED WITH CODE 1
Feb 23 16:09:35 account-create-submission-handler.scm: Empty value checks passed and chosen username not in use. 
Feb 23 16:09:35 account-create-submission-handler.scm: Email address xxx@xxx.xxx in use, but without a username.  Performing sql UPDATE... 
--
Feb 23 16:11:49 account-create-submission-handler.scm: Called... 
Feb 23 16:11:49 account-create-submission-handler.scm: Empty value checks passed and chosen username not in use. 
Feb 23 16:11:49 stderr: ERROR: In procedure pg-connectdb:
Feb 23 16:11:49 stderr: ERROR: could not send startup packet: Broken pipe
Feb 23 16:11:49 account-create: account-create.scm: EXITED WITH CODE 1
Feb 23 16:11:49 account-create-submission-handler.scm: Email address xxx@xxx.xxx in use, but without a username.  Performing sql UPDATE... 
Feb 23 16:11:50 account-create: #

[-- Attachment #3: Type: text/plain, Size: 135 bytes --]


-- 
Emacs' AlsaPlayer - Music Without Jolts
Lightweight, full-featured and mindful of your idyllic happiness.
http://home.gna.org/eap

Re: Broken pipe errors using guile-pg with guile 1.8

[Greg Troxel]

[-- Attachment #1: Type: text/plain, Size: 1851 bytes --]


Sebastian Tennant <sebyte@smolny.plus.com> writes:

> Hi Guilers,
>
> Is anyone familiar with the internals of guile-pg (version 0.16, author
> Ian Grant) which wraps PostgreSQL's libpq?

By 0.16, I think you mean ttn's version of Ian Grant's abandoned 0.07 or
so.

> I'm getting a lot of 'broken pipe' errors of the sort:
>
>  Feb 23 11:32:13 stderr: ERROR: In procedure pg-connectdb:
>  Feb 23 11:32:13 stderr: ERROR: could not send startup packet: Broken pipe
>
> It's especially bad at times of light load (rather than no load) and I
> never once noticed this error whilst the webapp was in development
> (i.e., I was the only person using it) which suggests to me that it's
> happening whenever two or more page requests call scripts that attempt
> to open database connections more or less at the same time.
>
> All my calls to pg-connectdb are let bound so database connections are
> (supposed to be) closed after every query.

I am not sure that gc will run as soon as you drop the reference, so you
might want to force gc, or better yet explicitly close the db object.
You could add a debug printf in the free/close function to check this
hypothesis, but I think you should be explicitly closing the connection
- gc should only be for memory, not external state - there's no hook to
run gc when guile is out of file descriptors, for example.

> Any advice very much appreciated.  I've attached a log extract to give
> you an idea of the frequency of failures.  I need to find a solution to
> this problem fast!
>
> Seb
>
> P.S. Perhaps upgrading guile-pg is the first thing I should try? IIRC
>      there's a more recent pkgsrc version (which is guile 1.8
>      comaptible) somewhere... hunting for it now.

I suspect a day or so of work would suffice to make the most recent
guile-pg work with 1.8.  If you do it definitely post patches.

[-- Attachment #2: Type: application/pgp-signature, Size: 193 bytes --]

Re: Broken pipe errors using guile-pg with guile 1.8

[Sebastian Tennant]

Quoth Greg Troxel <gdt@ir.bbn.com>:
> Sebastian Tennant <sebyte@smolny.plus.com> writes:
>> Is anyone familiar with the internals of guile-pg (version 0.16, author
>> Ian Grant) which wraps PostgreSQL's libpq?
>
> By 0.16, I think you mean ttn's version of Ian Grant's abandoned 0.07 or
> so.

It's the version shipped by Debian (deb modified by Dale Smith so that
it apt-installs without pulling in guile-1.6 as a dependency).  I
inspected the source (postgres.scm) to find the version number:

 ;;; Author: Ian Grant <xxx@xxx.xxx>

 (define-public (pg-guile-pg-module-version) "0.16")

On closer inspection, it probably is the version you're referring to as
ttn is the author of all the supplementary postgres-*.scm files included
in the package.

I know ttn's guile-pg (available from gnuvola.org) is much more
up-to-date but unfortunately it's only compatible with his guile-1.4.x
branch.

>> I'm getting a lot of 'broken pipe' errors of the sort:
>>
>>  Feb 23 11:32:13 stderr: ERROR: In procedure pg-connectdb:
>>  Feb 23 11:32:13 stderr: ERROR: could not send startup packet: Broken pipe
>>
>> It's especially bad at times of light load (rather than no load) and I
>> never once noticed this error whilst the webapp was in development
>> (i.e., I was the only person using it) which suggests to me that it's
>> happening whenever two or more page requests call scripts that attempt
>> to open database connections more or less at the same time.
>>
>> All my calls to pg-connectdb are let bound so database connections are
>> (supposed to be) closed after every query.
>
> I am not sure that gc will run as soon as you drop the reference, 

So you agree with my diagnosis?  Are there some arbitrary limits to how
many database connections (iniated by pg-connectdb) can remain open at
once?  There's no mention of that in the manual.

> so you might want to force gc, or better yet explicitly close the db
> object.

From the manual accompanying my version:

   "`Guile-pg' connections are closed when Guile's garbage collector
 collects the discarded object.  This only happens when the connection
 itself and all of the results of `pg-exec' are unreachable.  So to
 close the connection we just rebind the results from that connection
 and the connection symbol itself:

      guile> (define result '())
      guile> (define test '())

    Typically though the result and connection variables will be `let'
 bindings so the connection will usually be closed soon after the body
 of the `let' returns."          ^^^^^^^           ^^^^

I don't like the sound of 'usually' and 'soon' now that I read this
again in the light of the problems I'm experiencing.  Here's one of
scores of database procedures I've written for this particular web-app:

 (define (username-in-use? username)
   (let* ((dbconn (pg-connectdb "dbname=xxxx"))
          (q (pg-exec dbconn (sa "SELECT username FROM joblist "
                                 "WHERE username='" username "';"))))
     (> (pg-ntuples q) 0)))

I can't see how rebinding 'dbconn' and 'q' within this let form is going
to make any difference (plus I need a boolean return value, not
#unspecified as returned by set!).  Is this what you mean by "explicitly
closing the db object"?

Forcing gc after each procedure call which initiates a database
connection is a possible course of action.

> You could add a debug printf in the free/close function to check this
> hypothesis, 

As there are no free/close functions (everything is let bound) could you
be more specific as to how I could debug the cause of these broken
pipes?

>> P.S. Perhaps upgrading guile-pg is the first thing I should try? IIRC
>>      there's a more recent pkgsrc version (which is guile 1.8
>>      comaptible) somewhere... hunting for it now.
>
> I suspect a day or so of work would suffice to make the most recent
> guile-pg work with 1.8.  If you do it definitely post patches.

For C programmers perhaps, but not lowly scripters like myself.

Out of interest which do you consider the most recent guile-pg (ttn's or
some other, available from where)?

Regards,

Sebastian
-- 
Emacs' AlsaPlayer - Music Without Jolts
Lightweight, full-featured and mindful of your idyllic happiness.
http://home.gna.org/eap

Re: Broken pipe errors using guile-pg with guile 1.8

[Greg Troxel]

[-- Attachment #1: Type: text/plain, Size: 4589 bytes --]


Sebastian Tennant <sebyte@smolny.plus.com> writes:

> Quoth Greg Troxel <gdt@ir.bbn.com>:
>> Sebastian Tennant <sebyte@smolny.plus.com> writes:
>>
>> By 0.16, I think you mean ttn's version of Ian Grant's abandoned 0.07 or
>> so.
> On closer inspection, it probably is the version you're referring to as
> ttn is the author of all the supplementary postgres-*.scm files included
> in the package.

Yes, sounds like it.  I am only aware of three things with names like this

  guile-pg 0.07ish by Ian
  guile-pg ?-0.30ish, ttn-enhanced version of Ian's code
  pg-guile - BSD licensed, not maintained, totally different

> I know ttn's guile-pg (available from gnuvola.org) is much more
> up-to-date but unfortunately it's only compatible with his guile-1.4.x
> branch.

Not true - it works with 1.6

>>> All my calls to pg-connectdb are let bound so database connections are
>>> (supposed to be) closed after every query.
>>
>> I am not sure that gc will run as soon as you drop the reference, 
>
> So you agree with my diagnosis?  Are there some arbitrary limits to how
> many database connections (iniated by pg-connectdb) can remain open at
> once?  There's no mention of that in the manual.

I'm sure there are such limits, and suspect that most of those competent
to document them would have the same reaction I did :-)

>> so you might want to force gc, or better yet explicitly close the db
>> object.
>
> From the manual accompanying my version:
>
>    "`Guile-pg' connections are closed when Guile's garbage collector
>  collects the discarded object.  This only happens when the connection
>  itself and all of the results of `pg-exec' are unreachable.  So to
>  close the connection we just rebind the results from that connection
>  and the connection symbol itself:
>
>       guile> (define result '())
>       guile> (define test '())
>
>     Typically though the result and connection variables will be `let'
>  bindings so the connection will usually be closed soon after the body
>  of the `let' returns."          ^^^^^^^           ^^^^

Wow, that is funky.  I would expect an explicit pg-close that sets the
connection to a dead state and cleans up the state on the pg side.

> I don't like the sound of 'usually' and 'soon' now that I read this
> again in the light of the problems I'm experiencing.  Here's one of
> scores of database procedures I've written for this particular web-app:
>
>  (define (username-in-use? username)
>    (let* ((dbconn (pg-connectdb "dbname=xxxx"))
>           (q (pg-exec dbconn (sa "SELECT username FROM joblist "
>                                  "WHERE username='" username "';"))))
>      (> (pg-ntuples q) 0)))
>
> I can't see how rebinding 'dbconn' and 'q' within this let form is going
> to make any difference (plus I need a boolean return value, not
> #unspecified as returned by set!).  Is this what you mean by "explicitly
> closing the db object"?

No, I mean to call a close function so that the scheme object still
exists, but the PG object behind it has been closed.  In 0.37, there is
pg-finish.

> Forcing gc after each procedure call which initiates a database
> connection is a possible course of action.

By which I mean '(gc)' in your code.

>> You could add a debug printf in the free/close function to check this
>> hypothesis, 
>
> As there are no free/close functions (everything is let bound) could you
> be more specific as to how I could debug the cause of these broken
> pipes?

Edit the source to guile-pg and find the function that is called when gc
finds the smob.  That in 0.37 is called xc_free, and it has GC_PRINT.

>>> P.S. Perhaps upgrading guile-pg is the first thing I should try? IIRC
>>>      there's a more recent pkgsrc version (which is guile 1.8
>>>      comaptible) somewhere... hunting for it now.
>>
>> I suspect a day or so of work would suffice to make the most recent
>> guile-pg work with 1.8.  If you do it definitely post patches.
>
> For C programmers perhaps, but not lowly scripters like myself.
>
> Out of interest which do you consider the most recent guile-pg (ttn's or
> some other, available from where)?

Definitely 0.37, from http://www.gnuvola.org/software/guile-pg/

If you are not up to writing C code, then my advice is to change your
usage patterns to use very few database connection objects.  They can be
reused for each query, instead of being created and discarded all the
time.

See test/large.scm and test/meta.scm in 0.37; they both use pg-finish.

[-- Attachment #2: Type: application/pgp-signature, Size: 193 bytes --]