Forum OpenACS Q&A: nsoracle error?
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!
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?
Or should I resolve this issue first?
Thanks!
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.
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.
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.
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.
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
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.txtthis is a small test file
file -i markd-small.txtmarkd-small.txt: text/plain; charset=us-ascii
The RETURNED file (ns_ora clob_get_file):
cat markd-small.txt-backthis is a small test file
file -i markd-small.txt-backmarkd-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?