Forum OpenACS Q&A: Security related errors?

I'm using RedHat6.2, Postgresql6.5, and the latest version of ACS/PG
and the driver. (I assume they are the latest, I only downloaded them
last night.) And the binary of AOLServer 3.

I think most everything is working as it should be, insofar as I don't
get any error messages when I load the data model, and the postgres
drivers seem to query the database and return a response OK. However,
I can't find away around this error message that I keep getting.

From my logs:

-- quote begins --

[23/Apr/2000:20:40:14][25480.1026][-sched-] Notice: Querying '
    select section_url_stub
    from content_sections
    where scope='public'
    and requires_registration_p = 't';'
[23/Apr/2000:20:40:14][25480.1026][-sched-] Notice: nsd.db:
sql(localhost::acspg):
    select section_url_stub
    from content_sections
    where scope='public'
    and requires_registration_p = 't'
[23/Apr/2000:20:40:14][25480.1026][-sched-] Notice: Done running
scheduled proc ad_filter_restricted_content_sections.
[23/Apr/2000:20:40:26][25480.11790340][-conn0-] Notice: starting:
waiting for connections
[23/Apr/2000:20:40:26][25480.11790340][-conn0-] Notice: Querying
'select nextval('sec_id_seq') from dual;'
[23/Apr/2000:20:40:26][25480.11790340][-conn0-] Notice: nsd.db:
sql(localhost::acspg):  select nextval('sec_id_seq') from dual
[23/Apr/2000:20:40:26][25480.11790340][-conn0-] Notice: Querying
'select nextval('sec_id_seq') from dual;'
[23/Apr/2000:20:40:26][25480.11790340][-conn0-] Notice: nsd.db:
sql(localhost::acspg):  select nextval('sec_id_seq') from dual
[23/Apr/2000:20:40:27][25480.11790340][-conn0-] Notice: generating 1
random seed...
[23/Apr/2000:20:40:27][25480.11790340][-conn0-] Notice: seed
generation complete.
[23/Apr/2000:20:40:27][25480.11790340][-conn0-] Notice: Querying '
    insert into sec_sessions(session_id, user_id, token, secure_token,
browser_id,
    last_ip, last_hit)
    values(2, null, 'FPBcU0Aiu0mVX68Ar9Uxr00azTDdSItT', '', 1,
    '192.168.1.1', 956518827);'
[23/Apr/2000:20:40:27][25480.11790340][-conn0-] Notice: nsd.db:
sql(localhost::acspg):
    insert into sec_sessions(session_id, user_id, token, secure_token,
browser_id,
    last_ip, last_hit)
    values(2, null, 'FPBcU0Aiu0mVX68Ar9Uxr00azTDdSItT', '', 1,
    '192.168.1.1', 956518827)

[23/Apr/2000:20:40:27][25480.11790340][-conn0-] Notice: Querying
'select sec_rotate_last_visit(1, 956518827);'
[23/Apr/2000:20:40:27][25480.11790340][-conn0-] Error: Ns_PgExec:
result status: 7 message: ERROR:  No such function 'bpchar' with the
specified attributes

[23/Apr/2000:20:40:27][25480.11790340][-conn0-] Notice: nsd.db:
sql(localhost::acspg):  select sec_rotate_last_visit(1, 956518827)
[23/Apr/2000:20:40:27][25480.11790340][-conn0-] Error: Filter
sec_read_security_info returned error #1: Database operation "1row"
failed (exception NSDB, "Query was not a statement returning rows.")
[23/Apr/2000:20:40:27][25480.11790340][-conn0-] Error: nsd.tcl:
Invalid return code from filter proc: Critical filter
sec_read_security_info failed. (must be filter_ok, filter_return, or
filter_break)

-- quote ends --

I have some idea that this might have something to do with the new
permissions system in AOLServer3 (I've been using 2.3 till now) but
despite scrutinizing the manual, I can't see where I might have
anything wrong.

I'm starting up AOLserver using:

bin/nsd76 -u nsadmin -c acspg.ini

which *seems* right to me, but I've had problems with Aolserver
wanting to be started as root in the past before it would serve
pages. However, everything in the docs says AOLServer 3 won't run
as root, so I don't think it's that.

Any clues?

Basically, I keep on getting bounced back to the registration page. When I register, my data gets entered into the users table, but for some reason the system won't let me in.

From the logs again...

------ start quote -----

24/Apr/2000:03:46:56][13147.1026][-sched-] Notice: Registered partner cookie: ad
[24/Apr/2000:03:46:56][13147.1026][-sched-] Notice: Done running scheduled proc ad_partner_initialize.
[24/Apr/2000:03:47:06][13147.4100][-conn0-] Notice: starting: waiting for connections
[24/Apr/2000:03:47:06][13147.4100][-conn0-] Notice: Querying 'select first_names || ' ' || last_name as name from users where user_id = 1 and user_state <> 'deleted';'
[24/Apr/2000:03:47:06][13147.4100][-conn0-] Notice: nsd.db: sql(localhost::acspg):  select first_names || ' ' || last_name as name from users where user_id = 1 and user_state <> 'deleted'
[24/Apr/2000:03:47:06][13147.4100][-conn0-] Notice: Querying '
select section_url_stub, section_pretty_name
from content_sections
where scope='public' and enabled_p = 't'
order by sort_key, upper(section_pretty_name);'
[24/Apr/2000:03:47:06][13147.4100][-conn0-] Notice: nsd.db: sql(localhost::acspg):
select section_url_stub, section_pretty_name
from content_sections
where scope='public' and enabled_p = 't'
order by sort_key, upper(section_pretty_name)
[24/Apr/2000:03:47:08][13147.4100][-conn0-] Notice: nsd.db: opening:  postgres:localhost::acspg
[24/Apr/2000:03:47:08][13147.4100][-conn0-] Notice: Opening acspg on localhost
[24/Apr/2000:03:47:08][13147.4100][-conn0-] Notice: Ns_PgOpenDb(postgres):  Openned connection to localhost::acspg.
[24/Apr/2000:03:47:08][13147.4100][-conn0-] Notice: Querying 'set datestyle to 'ISO';'
[24/Apr/2000:03:47:08][13147.4100][-conn0-] Notice: Querying '
        select user_id, token, secure_token,
              last_ip, last_hit from sec_sessions
        where session_id = 2;'
[24/Apr/2000:03:47:08][13147.4100][-conn0-] Notice: nsd.db: sql(localhost::acspg):
        select user_id, token, secure_token,
              last_ip, last_hit from sec_sessions
        where session_id = 2

[24/Apr/2000:03:47:08][13147.5125][-conn1-] Notice: starting: waiting for connections
[24/Apr/2000:03:47:27][13147.4100][-conn0-] Notice: Querying 'select user_id, user_state, converted_p from users where upper(email)=upper('system');'
[24/Apr/2000:03:47:27][13147.4100][-conn0-] Notice: nsd.db: sql(localhost::acspg):  select user_id, user_state, converted_p from users where upper(email)=upper('system')
[24/Apr/2000:03:47:27][13147.4100][-conn0-] Notice: Querying '
        select password
        from users
        where user_id = 1
        and user_state='authorized';'
[24/Apr/2000:03:47:27][13147.4100][-conn0-] Notice: nsd.db: sql(localhost::acspg):
        select password
        from users
        where user_id = 1
        and user_state='authorized'

[24/Apr/2000:03:47:27][13147.4100][-conn0-] Notice: Querying '
        update sec_sessions
        set user_id = 1
        where session_id = 2;'
[24/Apr/2000:03:47:27][13147.4100][-conn0-] Notice: nsd.db: sql(localhost::acspg):
        update sec_sessions
        set user_id = 1
        where session_id = 2

[24/Apr/2000:03:47:27][13147.4100][-conn0-] Notice: Querying 'select password from users where user_id = 1;'
[24/Apr/2000:03:47:27][13147.4100][-conn0-] Notice: nsd.db: sql(localhost::acspg):  select password from users where user_id = 1
[24/Apr/2000:03:47:29][13147.4100][-conn0-] Notice: Querying 'update users
set last_visit = sysdate(),
    second_to_last_visit = last_visit,
    n_sessions = n_sessions + 1
where user_id = 1;'
[24/Apr/2000:03:47:29][13147.4100][-conn0-] Notice: nsd.db: sql(localhost::acspg):  update users
set last_visit = sysdate(),
    second_to_last_visit = last_visit,
    n_sessions = n_sessions + 1
where user_id = 1
[24/Apr/2000:03:47:29][13147.4100][-conn0-] Notice: Querying 'update session_statistics
set repeat_count = repeat_count + 1
where entry_date = trunc(sysdate());'
[24/Apr/2000:03:47:29][13147.4100][-conn0-] Notice: nsd.db: sql(localhost::acspg):  update session_statistics
set repeat_count = repeat_count + 1
where entry_date = trunc(sysdate())
[24/Apr/2000:03:47:33][13147.5125][-conn1-] Notice: Querying '
        select user_id, token, secure_token,
              last_ip, last_hit from sec_sessions
        where session_id = 2;'
[24/Apr/2000:03:47:33][13147.5125][-conn1-] Notice: nsd.db: sql(localhost::acspg):
        select user_id, token, secure_token,
              last_ip, last_hit from sec_sessions
        where session_id = 2

[24/Apr/2000:03:49:33][13147.5125][-conn1-] Notice: exiting: no waiting connections
[24/Apr/2000:03:49:33][13147.4100][-conn0-] Notice: exiting: no waiting connections

--- End quote ---

Sure, I could have put <pre> tags on, but I can't see that it would
have made much difference given that the lines wouldn't fit in the browser anyway?

I recommend you upgrade to the latest Postgres 7.0 beta. We're not planning to support PG 6.5 with ACS 3.2.2.  This may or may not help you with your problem, but you should do it anyway (and I do believe the beta release notes point that we won't continue to support ACS/pg on 6.5?)

It looks to me as though the backend might be crashing, but I don't see any error in the log.  It appears you have verbose set true for the pool, do you also have logsqlerrors enabled?

If not, do so, try again and post log results here.

If you do have logsqlerrors enabled, then the problem's not with the database interaction but lies somewhere else, and at the moment I'm fresh out of ideas.

bpchar is an internal function, a type cast I think???  (it's early, I haven't had my coffee, my mind's more feeble than normal).

Probably a case where it was noticed that type coverage for this internal function was incomplete and it got fixed in 7.0.  There was quite a bit of such stuff involving type casting and just missing
operators that got in to this release (I added the ability to have an index on columns of boolean type, for instance).

openACS 3.2.2 must've stumbled into such a case.

Referential integrity's been implemented

An annoying "group by" bug that uglified some ACS pages in a non-fatal manner has been fixed.

Lots of small bugs like the one mentioned above have been fixed.

A lot of work was done on the optimizer, on average queries should run  faster.

The back end now tracks which backend dirties which blocks, which will  lower the number of blocks written at transaction end and fixes a potential database-corrupting race condition.

A new lzText type will allow 32KB text in a 16KB block, which means it  will be easy to change bboard and other modules to allow for full TEXTAREA-sized messages

The new PSQL is really nice (the old one was already much more user-friendly than SQL*Plus)

These are the things that come to mind that directly impact our openACS/pg implementation.

If the above doesn't motivate you, what will? :)

Final release is currently scheduled for Sunday, May 1, so you might want to hold off just a few more days.