Forum OpenACS Q&A: nsoracle error?

Collapse
Posted by Abrantes Filho on
Well, I d'ont know if this is the correct forum to post, but I could not find exactly where I should post my question.

I'm installing an AOLserver 4.5.1 for a OpenACS site in our development server, and I'm having a little trouble with nsoracle.

Tech information about the web server environment:
- openSUSE 11.2, 32 bits
- AOLserver 4.5.1
- nsoracle 2.7
- Oracle Client 11.2.0.3.0

Everything was installed according instructions and I could connect AOLserver with our database server without any problems.

Please, visit the following URLs:

- AOLserver 4.5.1 installation:
http://desenv.saudenaweb.com.br:84/

- AOLserver connection test page with our database server (just a "select sysdate from dual" from Oracle):
http://desenv.saudenaweb.com.br:84/db.adp

Until now I could install AOLserver 4.5.1 and connect it to our database server.

But, when I try to test the nsoracle installation with the tests scripts provided by nsoracle, I got an error with the "clob-test.tcl" test. All other tests were done whit success. Please, visit the following URLs:

- table-test.tcl: OK
http://desenv.saudenaweb.com.br:84/nsoracle/table-test.tcl

- bind-test.tcl: OK
http://desenv.saudenaweb.com.br:84/nsoracle/bind-test.tcl

- error-test.tcl: OK
http://desenv.saudenaweb.com.br:84/nsoracle/error-test.tcl

- clob-test.tcl: ERROR!!
http://desenv.saudenaweb.com.br:84/nsoracle/clob-test.tcl

This last test, "clob-test.tcl", starts to run but exit with an error just after the first *lob_*_file tests.

AOLserver log show this:
[05/Aug/2012:10:22:48][32340.3025718128][-default:0-] Error: Tcl exception:

while executing
"ns_ora clob_get_file $db "select chunks from markd_lob_test where lob_id=100" ${empty_file_name}-back"
(file "/srv/www/aolserver/server1/www/nsoracle/clob-test.tcl" line 454)
invoked from within
"source $file"
invoked from within
"ns_sourceproc cns53 {}"

The docs for nsoracle (http://desenv.saudenaweb.com.br:84/nsoracle/doc/) clearly indicates that the "ns_ora clob_get_file" is part of the extended api.

I did not installed the openACS because of this failed test with nsoracle.

So, any ideas on how can I correct this lob problema with nsoracle?

Thanks!

Collapse
2: Re: nsoracle error? (response to 1)
Posted by Dave Bauer on
Hi, can you provide some more surrounding context from the error log, especially before the part you posted? There is not enough information to help.
Collapse
3: Re: nsoracle error? (response to 2)
Posted by Abrantes Filho on
Hi, thanks for you help.

I restarted the AOLserver and tryed to acess the clob-test.tcl page again. All logs from AOLserver, since the restart, are here:

[06/Aug/2012:10:24:48][25854.3074164416][-main-] Notice: nsmain: AOLserver/4.5.1 starting
[06/Aug/2012:10:24:48][25854.3074164416][-main-] Notice: nsmain: security info: uid=30, euid=30, gid=8, egid=8
[06/Aug/2012:10:24:48][25854.3074164416][-main-] Notice: nsmain: max files: FD_SETSIZE = 1024, rl_cur = 8192, rl_max = 8192
[06/Aug/2012:10:24:48][25854.3074164416][-main-] Warning: nsmain: rl_max > FD_SETSIZE
[06/Aug/2012:10:24:48][25854.3074164416][-main-] Notice: encoding: loaded: utf-8
[06/Aug/2012:10:24:48][25854.3074164416][-main-] Notice: fastpath[server1]: mapped GET /
[06/Aug/2012:10:24:48][25854.3074164416][-main-] Notice: fastpath[server1]: mapped HEAD /
[06/Aug/2012:10:24:48][25854.3074164416][-main-] Notice: fastpath[server1]: mapped POST /
[06/Aug/2012:10:24:48][25854.3074164416][-main-] Notice: adp[server1]: mapped GET /*.adp
[06/Aug/2012:10:24:48][25854.3074164416][-main-] Notice: adp[server1]: mapped HEAD /*.adp
[06/Aug/2012:10:24:48][25854.3074164416][-main-] Notice: adp[server1]: mapped POST /*.adp
[06/Aug/2012:10:24:48][25854.3074164416][-main-] Notice: modload: loading '/usr/local/aolserver/bin/nssock.so'
[06/Aug/2012:10:24:48][25854.3074164416][-main-] Notice: modload: loading '/usr/local/aolserver/bin/nslog.so'
[06/Aug/2012:10:24:48][25854.3074164416][-main-] Notice: nslog: opened '/usr/local/aolserver/servers/server1/modules/nslog/access.log'
[06/Aug/2012:10:24:48][25854.3074164416][-main-] Notice: modload: loading '/usr/local/aolserver/bin/nsdb.so'
[06/Aug/2012:10:24:48][25854.3074164416][-main-] Notice: modload: loading '/usr/local/aolserver/bin/nsoracle.so'
[06/Aug/2012:10:24:49][25854.3074164416][-main-] Notice: ora11 driver LobBufferSize = 32768
[06/Aug/2012:10:24:49][25854.3074164416][-main-] Notice: ora11 driver PrefetchRows = 0
[06/Aug/2012:10:24:49][25854.3074164416][-main-] Notice: ora11 driver PrefetchMemory = 0
[06/Aug/2012:10:24:50][25854.3074164416][-main-] Notice: Loaded ArsDigita Oracle Driver version 2.7, built on 15:01:46/Aug 2 2012
[06/Aug/2012:10:24:50][25854.3074164416][-main-] Notice: modload: loading '/usr/local/aolserver/bin/nscache.so'
[06/Aug/2012:10:24:50][25854.3074164416][-main-] Notice: nscache module version 1.5 server: server1
[06/Aug/2012:10:24:50][25854.3074164416][-main-] Notice: conf: [ns/server/server1]enabletclpages = 1
[06/Aug/2012:10:24:50][25854.3074164416][-main-] Notice: tcl: enabling .tcl pages
[06/Aug/2012:10:24:50][25854.3074164416][-main-] Notice: default thread pool: minthreads 5 maxthreads 20 idle 0 current 0 maxconns 100 queued 0 timeout 120 spread 20
[06/Aug/2012:10:24:51][25854.3074164416][-main-] Notice: XOTcl version 1.6.6 loaded
[06/Aug/2012:10:24:51][25854.3074164416][-main-] Notice: nsmain: AOLserver/4.5.1 running
[06/Aug/2012:10:24:51][25854.3074164416][-main-] Notice: nsmain: security info: uid=30, euid=30, gid=8, egid=8
[06/Aug/2012:10:24:51][25854.3065711472][-sched-] Notice: sched: starting
[06/Aug/2012:10:24:51][25854.3074164416][-main-] Notice: driver: starting: nssock
[06/Aug/2012:10:24:51][25854.3025562480][-default:0-] Notice: random: generating 1 seed
[06/Aug/2012:10:24:51][25854.3024538480][-nssock:driver-] Notice: starting
[06/Aug/2012:10:24:51][25854.3024538480][-nssock:driver-] Notice: nssock: listening on 200.179.110.80:84
[06/Aug/2012:10:25:06][25854.3025562480][-default:0-] Notice: dbdrv: opening database 'ora11:snw'
[06/Aug/2012:10:25:09][25854.3025562480][-default:0-] Error: Tcl exception:
while executing
"ns_ora clob_get_file $db "select chunks from markd_lob_test where lob_id=100" ${empty_file_name}-back"
(file "/srv/www/aolserver/server1/www/nsoracle/clob-test.tcl" line 492)
invoked from within
"source $file"
invoked from within
"ns_sourceproc cns0 {}"

Above are all logs genereted since the AOLserver restart and a try to run clob-test.tcl again.

The only error message in the log are about "ns_ora clob_get_file".

I'm doing something wrong?

Collapse
4: Re: nsoracle error? (response to 1)
Posted by Abrantes Filho on
Could I just ignore this lob problema and just continue on OpenACS installation?

Or should I resolve this issue first?

Thanks!

Collapse
5: Re: nsoracle error? (response to 1)
Posted by Dave Bauer on
Is there any more information about the actual error in the logs? It says Tcl Exception, but that doesn't explain what the actual problem was.
Collapse
6: Re: nsoracle error? (response to 5)
Posted by Abrantes Filho on
No, the log just show exactly that message.

I restarted AOLserver whit the parameter "set debug true" and just access the clob-test.tcl again. Here are the logs with debug parameter set to true:

[09/Aug/2012:10:12:26][14557.3074852544][-main-] Notice: nsmain: AOLserver/4.5.1 starting
[09/Aug/2012:10:12:26][14557.3074852544][-main-] Notice: nsmain: security info: uid=30, euid=30, gid=8, egid=8
[09/Aug/2012:10:12:26][14557.3074852544][-main-] Notice: nsmain: max files: FD_SETSIZE = 1024, rl_cur = 8192, rl_max = 8192
[09/Aug/2012:10:12:26][14557.3074852544][-main-] Warning: nsmain: rl_max > FD_SETSIZE
[09/Aug/2012:10:12:26][14557.3074852544][-main-] Notice: encoding: loaded: utf-8
[09/Aug/2012:10:12:26][14557.3074852544][-main-] Notice: fastpath[server1]: mapped GET /
[09/Aug/2012:10:12:26][14557.3074852544][-main-] Notice: fastpath[server1]: mapped HEAD /
[09/Aug/2012:10:12:26][14557.3074852544][-main-] Notice: fastpath[server1]: mapped POST /
[09/Aug/2012:10:12:26][14557.3074852544][-main-] Notice: adp[server1]: mapped GET /*.adp
[09/Aug/2012:10:12:26][14557.3074852544][-main-] Notice: adp[server1]: mapped HEAD /*.adp
[09/Aug/2012:10:12:26][14557.3074852544][-main-] Notice: adp[server1]: mapped POST /*.adp
[09/Aug/2012:10:12:26][14557.3074852544][-main-] Notice: modload: loading '/usr/local/aolserver/bin/nssock.so'
[09/Aug/2012:10:12:26][14557.3074852544][-main-] Notice: modload: loading '/usr/local/aolserver/bin/nslog.so'
[09/Aug/2012:10:12:26][14557.3074852544][-main-] Notice: nslog: opened '/usr/local/aolserver/servers/server1/modules/nslog/access.log'
[09/Aug/2012:10:12:26][14557.3074852544][-main-] Notice: modload: loading '/usr/local/aolserver/bin/nsdb.so'
[09/Aug/2012:10:12:26][14557.3074852544][-main-] Notice: modload: loading '/usr/local/aolserver/bin/nsoracle.so'
[09/Aug/2012:10:12:28][14557.3074852544][-main-] Notice: ora11 driver LobBufferSize = 32768
[09/Aug/2012:10:12:28][14557.3074852544][-main-] Notice: ora11 driver PrefetchRows = 0
[09/Aug/2012:10:12:28][14557.3074852544][-main-] Notice: ora11 driver PrefetchMemory = 0
[09/Aug/2012:10:12:29][14557.3074852544][-main-] Notice: Loaded ArsDigita Oracle Driver version 2.7, built on 15:01:46/Aug 2 2012
[09/Aug/2012:10:12:29][14557.3074852544][-main-] Notice: modload: loading '/usr/local/aolserver/bin/nscache.so'
[09/Aug/2012:10:12:29][14557.3074852544][-main-] Notice: nscache module version 1.5 server: server1
[09/Aug/2012:10:12:29][14557.3074852544][-main-] Notice: conf: [ns/server/server1]enabletclpages = 1
[09/Aug/2012:10:12:29][14557.3074852544][-main-] Notice: tcl: enabling .tcl pages
[09/Aug/2012:10:12:29][14557.3074852544][-main-] Notice: default thread pool: minthreads 5 maxthreads 20 idle 0 current 0 maxconns 100 queued 0 timeout 120 spread 20
[09/Aug/2012:10:12:30][14557.3074852544][-main-] Notice: XOTcl version 1.6.6 loaded
[09/Aug/2012:10:12:30][14557.3074852544][-main-] Notice: nsmain: AOLserver/4.5.1 running
[09/Aug/2012:10:12:30][14557.3074852544][-main-] Notice: nsmain: security info: uid=30, euid=30, gid=8, egid=8
[09/Aug/2012:10:12:30][14557.3066399600][-sched-] Notice: sched: starting
[09/Aug/2012:10:12:30][14557.3074852544][-main-] Notice: driver: starting: nssock
[09/Aug/2012:10:12:30][14557.3026250608][-default:0-] Notice: random: generating 1 seed
[09/Aug/2012:10:12:30][14557.3025226608][-nssock:driver-] Notice: starting
[09/Aug/2012:10:12:30][14557.3025226608][-nssock:driver-] Notice: nssock: listening on 200.179.110.80:84
[09/Aug/2012:10:13:09][14557.3026250608][-default:0-] Notice: dbdrv: opening database 'ora11:snw'
[09/Aug/2012:10:13:10][14557.3026250608][-default:0-] Notice: dbinit: sql(snw): 'drop table markd_lob_test'
[09/Aug/2012:10:13:10][14557.3026250608][-default:0-] Notice: dbinit: sql(snw): 'create table markd_lob_test (lob_id integer, chunks clob, blunks blob)'
[09/Aug/2012:10:13:10][14557.3026250608][-default:0-] Notice: SQL():
insert into markd_lob_test (lob_id, chunks)
values (0, empty_clob())
returning chunks into :1
[09/Aug/2012:10:13:11][14557.3026250608][-default:0-] Notice: CLOB # 0, length 67: This is a small lob. There are many like it, but this one is mine.
[09/Aug/2012:10:13:11][14557.3026250608][-default:0-] Notice: dbinit: sql(snw): 'select chunks from markd_lob_test where lob_id = 0'
[09/Aug/2012:10:13:11][14557.3026250608][-default:0-] Notice: SQL():
insert into markd_lob_test (lob_id, chunks)
values (1, empty_clob())
returning chunks into :1
[09/Aug/2012:10:13:11][14557.3026250608][-default:0-] Notice: CLOB # 0, length 0: (NULL)
[09/Aug/2012:10:13:11][14557.3026250608][-default:0-] Notice: dbinit: sql(snw): 'select chunks from markd_lob_test where lob_id = 1'
[09/Aug/2012:10:13:11][14557.3026250608][-default:0-] Notice: SQL():
insert into markd_lob_test (lob_id, blunks)
values (2, empty_blob())
returning blunks into :1
[09/Aug/2012:10:13:11][14557.3026250608][-default:0-] Notice: CLOB # 0, length 67: This is a small lob. There are many like it, but this one is mine.
[09/Aug/2012:10:13:11][14557.3026250608][-default:0-] Notice: dbinit: sql(snw): 'select blunks from markd_lob_test where lob_id = 2'
[09/Aug/2012:10:13:11][14557.3026250608][-default:0-] Notice: SQL():
insert into markd_lob_test (lob_id, blunks)
values (3, empty_blob())
returning blunks into :1
[09/Aug/2012:10:13:11][14557.3026250608][-default:0-] Notice: CLOB # 0, length 0: (NULL)
[09/Aug/2012:10:13:11][14557.3026250608][-default:0-] Notice: dbinit: sql(snw): 'select blunks from markd_lob_test where lob_id = 3'
[09/Aug/2012:10:13:11][14557.3026250608][-default:0-] Notice: SQL():
update markd_lob_test set chunks = empty_clob()
where lob_id = 0
returning chunks into :1
[09/Aug/2012:10:13:11][14557.3026250608][-default:0-] Notice: CLOB # 0, length 139: This is a small lob. There are many like it, but this one is mine. This is a small lob. There are many like it, but this one is mine.
[09/Aug/2012:10:13:11][14557.3026250608][-default:0-] Notice: dbinit: sql(snw): 'select chunks from markd_lob_test where lob_id = 0'
[09/Aug/2012:10:13:11][14557.3026250608][-default:0-] Notice: SQL():
update markd_lob_test set chunks = empty_clob()
where lob_id = 0
returning chunks into :1
[09/Aug/2012:10:13:11][14557.3026250608][-default:0-] Notice: CLOB # 0, length 1: a
[09/Aug/2012:10:13:11][14557.3026250608][-default:0-] Notice: dbinit: sql(snw): 'select chunks from markd_lob_test where lob_id = 0'
[09/Aug/2012:10:13:11][14557.3026250608][-default:0-] Notice: SQL():
update markd_lob_test set chunks = empty_clob()
where lob_id = 0
returning chunks into :1
[09/Aug/2012:10:13:11][14557.3026250608][-default:0-] Notice: CLOB # 0, length 0: (NULL)
[09/Aug/2012:10:13:12][14557.3026250608][-default:0-] Notice: dbinit: sql(snw): 'select chunks from markd_lob_test where lob_id = 0'
[09/Aug/2012:10:13:12][14557.3026250608][-default:0-] Notice: dbinit: sql(snw): '
update markd_lob_test set chunks = empty_clob()
where lob_id = 0'
[09/Aug/2012:10:13:12][14557.3026250608][-default:0-] Notice: dbinit: sql(snw): 'select chunks from markd_lob_test where lob_id = 0'
[09/Aug/2012:10:13:12][14557.3026250608][-default:0-] Notice: SQL():
update markd_lob_test set blunks = empty_blob()
where lob_id = 0
returning blunks into :1
[09/Aug/2012:10:13:12][14557.3026250608][-default:0-] Notice: CLOB # 0, length 139: This is a small lob. There are many like it, but this one is mine. This is a small lob. There are many like it, but this one is mine.
[09/Aug/2012:10:13:12][14557.3026250608][-default:0-] Notice: dbinit: sql(snw): 'select blunks from markd_lob_test where lob_id = 0'
[09/Aug/2012:10:13:12][14557.3026250608][-default:0-] Notice: SQL():
update markd_lob_test set blunks = empty_blob()
where lob_id = 0
returning blunks into :1
[09/Aug/2012:10:13:12][14557.3026250608][-default:0-] Notice: CLOB # 0, length 1: a
[09/Aug/2012:10:13:12][14557.3026250608][-default:0-] Notice: dbinit: sql(snw): 'select blunks from markd_lob_test where lob_id = 0'
[09/Aug/2012:10:13:12][14557.3026250608][-default:0-] Notice: SQL():
update markd_lob_test set blunks = empty_blob()
where lob_id = 0
returning blunks into :1
[09/Aug/2012:10:13:12][14557.3026250608][-default:0-] Notice: CLOB # 0, length 0: (NULL)
[09/Aug/2012:10:13:12][14557.3026250608][-default:0-] Notice: dbinit: sql(snw): 'select blunks from markd_lob_test where lob_id = 0'
[09/Aug/2012:10:13:12][14557.3026250608][-default:0-] Notice: dbinit: sql(snw): '
update markd_lob_test set blunks = empty_blob()
where lob_id = 0'
[09/Aug/2012:10:13:12][14557.3026250608][-default:0-] Notice: dbinit: sql(snw): 'select blunks from markd_lob_test where lob_id = 0'
[09/Aug/2012:10:13:12][14557.3026250608][-default:0-] Notice: SQL():
insert into markd_lob_test (lob_id, chunks)
values (100, empty_clob())
returning chunks into :1
[09/Aug/2012:10:13:12][14557.3026250608][-default:0-] Notice: CLOB # 0, file name /tmp/markd-empty.txt
[09/Aug/2012:10:13:12][14557.3026250608][-default:0-] Notice: SQL(): select chunks from markd_lob_test where lob_id=100
[09/Aug/2012:10:13:12][14557.3026250608][-default:0-] Error: Tcl exception:

while executing
"ns_ora clob_get_file $db "select chunks from markd_lob_test where lob_id=100" ${empty_file_name}-back"
(file "/srv/www/aolserver/server1/www/nsoracle/clob-test.tcl" line 492)
invoked from within
"source $file"
invoked from within
"ns_sourceproc cns0 {}"

The log ends here.

As you can see, even with debug set to true, the Tcl exception message is very little informative.

Collapse
7: Re: nsoracle error? (response to 1)
Posted by Dave Bauer on
Thanks for responding.

What version of AOLserver and Tcl and Oracle are you using.

How did you install them, compiled, or packaged?

I haven't used Oracle in a long time, but usually the error messages are more informative.

Collapse
8: Re: nsoracle error? (response to 7)
Posted by Abrantes Filho on
Hi, thank you for your message.

On the webserver (openSUSE 11.2, 32 bits):
- AOLserver 4.5.1
- TCL 8.5.12
- Oracle Client 11.2.0.3.0 (32 bits)

On the oracle server (SuSE Linux Enterprise Server 11 SP2, 64 bits):
- Oracle Server 11.2.0.3.0

I install AOLserver, TCL and nsoracle acconding the install instructions on openACS website, execpt that I don't used the sources on Git repository: I have downloaded the source from sf.net (http://sourceforge.net/projects/aolserver/files/), and compiled on my server according the instructions on openACS site.

Everytinhg happens very successfuly, except when I try to run the tests files on nsoracle source. The clob test failed.

Please note that some TCL procs on these nsoracle source files was missing, so I search the documentation on openACS site and just edit the files to include the procs. For example: the test files use the ReturnHeaders proc. I search on openACS site (and sources files) and included this on the test files:

proc util_WriteWithExtraOutputHeaders {headers_so_far {first_part_of_page ""}} {
set set_headers_i 0
set set_headers_limit [ns_set size [ns_conn outputheaders]]
while {$set_headers_i < $set_headers_limit} {
append headers_so_far "[ns_set key [ns_conn outputheaders] $set_headers_i]: [ns_set value [ns_conn outputheaders] $set_headers_i]\n"
incr set_headers_i
}
append entire_string_to_write $headers_so_far "\n" $first_part_of_page
ns_write $entire_string_to_write
}

proc ReturnHeaders {{content_type text/html}} {
set all_the_headers "HTTP/1.0 200 OK
MIME-Version: 1.0
Content-Type: $content_type\n"
util_WriteWithExtraOutputHeaders $all_the_headers
}

When I include the missing procs, all test files could be run and all, but the clob-test.tcl, run whiout error.

Collapse
9: Re: nsoracle error? (response to 8)
Posted by Gustaf Neumann on
i have no oracle, but it seems as if the nsoracle driver has a problem returning the values saved from an empty_clob to a file. If you connect to the database, and check the content of the table "markd_lob_test", does it look correct?

The test you are running is from nsoracle and not from OpenACS. It might be possible, that writing empty_lobs to files and vice versa is not needed from OpenACS. Do you intend to use OpenACS? Note that OpenACS has quite a large regression test.

Collapse
10: Re: nsoracle error? (response to 1)
Posted by Abrantes Filho on
Well, I'm still working on this and I think I'm getting close to a solution. Now I could run all the "clob-test.tcl" page until its end, with only some problems.

I did this:

First, I got the newer sources of nsoracle from git (git://github.com/aolserver/nsoracle.gi) and compiled whit the instructions on openACS site.

Next, I have installed this newer nsoracle into my AOLserver install.

Then, I did all of tests again:

http://desenv.saudenaweb.com.br:84/nsoracle/table-test.tcl

http://desenv.saudenaweb.com.br:84/nsoracle/bind-test.tcl

http://desenv.saudenaweb.com.br:84/nsoracle/error-test.tcl

http://desenv.saudenaweb.com.br:84/nsoracle/clob-test.tcl

As before, the table-test, the bind-test and the error-test just finished without error.

But this time, the clob-test could be run, with just some errors (the clob-test with nsoracle 2.7 never gets to the end of test, but with the newer sources from git, the test could be run).

Now I need to figure out the erros (in red font) on the clob-test below:
http://desenv.saudenaweb.com.br:84/nsoracle/clob-test.tcl

Collapse
11: Re: nsoracle error? (response to 10)
Posted by Abrantes Filho on
Just another information:

The "ns_ora clob_dml_file" correctly inserted a small file as clob in the test table.

The problem is with "ns_ora clob_get_file": when selecting the clob and writing it to a return file, the resulting file have a binary charset, and so a diff between the original file and the retrurned file fails (should be equal).

The ORIGINAL file inserted on database (ns_ora clob_dml_file):

cat markd-small.txt
this is a small test file

file -i markd-small.txt
markd-small.txt: text/plain; charset=us-ascii

The RETURNED file (ns_ora clob_get_file):

cat markd-small.txt-back
this is a small test file

file -i markd-small.txt-back
markd-small.txt-back: text/plain; charset=binary

Now, aparently the problem is in ns_ora clob_get_file: it is writing a "binary" file insted of a "character" file.

Any ideas?