Forum OpenACS Development: Problems writing blob content to the connection with nsoracle drive and NaviServer

We are moving an old version of ACS (Kernel 4.2) with an Oracle back-end to the latest NaviServer (4.99.24) and we ran into problems returning files stored in the database using "ns_ora write_blob ..." We came across the issue while testing File Storage where the PDF files we download appear to be mangled/corrupted. This results in files having a larger file size than expected and rendering with blank pages. After inspecting the contents with a hex editor we saw what appeared to be double encoding of some characters.

We also tested writing the files to the filesystem using "ns_ora blob_get_file ..." without any problems and we confirmed that files are corrupted when returned to the connection and not when being written to the database.

Below are the two tests we ran that show the problem. We also ran these test on a new oacs/navisever/oracle install and we observed the same download problem. Any ideas of what could be the cause?

Original System:
-----------------
AOLserver 4.5.1
Oracle Driver version 2.8a1
TCL 8.5.19

Updated System:
--------------
NaviServer 4.99.24 (tar-4.99.24)
Oracle Driver version 2.8
TCL 8.6.12

Test Script w/Issue:

set version_id 325997875

db_1row file_type {     select mime_type     , dbms_lob.getlength(content) as content_length     from   cr_revisions     where  revision_id = :version_id }

set db [ns_db gethandle subquery]

ns_headers -binary -- 200 $mime_type $content_length

ns_ora write_blob $db " select content from cr_revisions where revision_id = $version_id"

ns_db releasehandle $db

Log

[28/Nov/2022:17:58:14][112424.7f4e0effd700][-driver:nssock:0-] Debug(ns:driver): SockSetServer request line 'GET /test/fs-download HTTP/1.0' get location from mapping 'http://127.0.0.1:8080';
[28/Nov/2022:17:58:14][112424.7f4e0effd700][-driver:nssock:0-] Debug(ns:driver): SockSetServer host 'ng1.myserver.org' request line 'GET /test/fs-download HTTP/1.0' final location 'http://127.0.0.1:8080';
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:142-] Debug(ns:driver): NsGetRequest got the pre-parsed request gt GET /test/fs-download HTTP/1.0 lt from the driver
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Dev: config: ns/server/myserver/acs/request-processor:DebugP value= (string)
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Dev: config: ns/server/myserver/acs/request-processor:LogDebugP value= (string)
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Dev: config: ns/server/myserver/acs/request-processor:UseOpenACSSecHandlerP value= (string)
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Warning: APM: UseOpenACSSecHandlerP does not exist
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Dev: config: ns/parameters:ReverseProxyMode value=true (string)
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Debug(sql): SQL():
:        select count(*)
:          from dual
:         where acs_permission.permission_p(:object_id, :user_id, :privilege) = 't'
:
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Debug(sql): bind variable 'object_id' = '1435'
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Debug(sql): bind variable 'user_id' = '0'
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Debug(sql): bind variable 'privilege' = 'read'
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Dev: config: ns/server/myserver/acs/request-processor:ExtensionPrecedence value= (string)
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Dev: config: ns/server/myserver/acs/dummy:RefreshCache value= (string)
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Debug(sql): SQL():
:        select mime_type
:        , dbms_lob.getlength(content) as content_length
:        from   cr_revisions
:        where  revision_id = :version_id
:
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Debug(sql): bind variable 'version_id' = '314417727'
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Debug(sql): SQL():
:        select content
:        from   cr_revisions
:        where  revision_id = 314417727
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Debug(request): headers:
:    HTTP/1.0 200 OK\x0d
:    Server: NaviServer/4.99.24\x0d
:    Date: Tue, 29 Nov 2022 01:58:14 GMT\x0d
:    Content-Type: application/pdf\x0d
:    Content-Length: 32132\x0d
:    Connection: close\x0d
:    X-Frame-Options: SAMEORIGIN\x0d
:    X-Content-Type-Options: nosniff\x0d
:    X-XSS-Protection: 1; mode=block\x0d
:    Referrer-Policy: strict-origin\x0d
:
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Debug(ns:driver): NsWriterQueue: size 43931 bufs 0x7f4e20835300 (2) flags 1030050 stream 000040 chan (nil) fd -1 thread 2
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Debug(ns:driver): NsSockClose sockPtr 0x7f4df401dab0 (21) keep 0
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Debug(ns:driver): NsSockClose calls RequestFree
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Debug(ns:driver): === RequestFree cleans 0x7f4df400f810 (avail 0 keep 0 length 0 contentLength 0)
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Debug(ns:driver): RequestFree does not call Ns_ResetRequest on 0x7f4df400f818
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Debug(ns:driver): === Push request structure 0x7f4df400f810 in (to pool)
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Debug(request): connection closed
[28/Nov/2022:17:58:14][112424.7f4e20836700][-conn:myserver:default:6:143-] Debug(request): end GET /test/fs-download HTTP/1.0
[28/Nov/2022:17:58:14][112424.7f4e0effd700][-driver:nssock:0-] Debug(ns:driver): === PollWait returned 1, trigger[0] 1
[28/Nov/2022:17:58:14][112424.7f4e0effd700][-driver:nssock:0-] Debug(ns:driver): SockRelease reason SOCK_CLOSE err 11 (sock -1)
[28/Nov/2022:17:58:14][112424.7f4e0effd700][-driver:nssock:0-] Debug(ns:driver): SockRelease bypasses SockClose, since we have an invalid socket
[28/Nov/2022:17:58:14][112424.7f4e0effd700][-driver:nssock:0-] Debug(ns:driver): DRIVER SockRelease: errno 11 drvPtr->closewait 2.000000

Test Script that Works (writing file to filesystem):

set fpath "/path/to/my.pdf"

db_with_handle db {     ns_ora blob_get_file $db "     select content     from   cr_revisions     where  revision_id = $version_id" $fpath }

ns_returnfile 200 "application/pdf" $fpath

Log

[27/Nov/2022:14:28:51][75236.7f975e039700][-conn:myserver:default:3:2121-] Debug(sql): SQL():
:        select mime_type
:        , dbms_lob.getlength(content) as content_length
:        from   cr_revisions
:        where  revision_id = :version_id
:
[27/Nov/2022:14:28:51][75236.7f975e039700][-conn:myserver:default:3:2121-] Debug(sql): bind variable 'version_id'
= '325997875'
[27/Nov/2022:14:28:51][75236.7f975e039700][-conn:myserver:default:3:2121-] Debug(sql): SQL():
:        select content
:        from   cr_revisions
:        where  revision_id = 325997875
[27/Nov/2022:14:28:51][75236.7f975e039700][-conn:myserver:default:3:2121-] Debug(ns:driver): NsWriterQueue: size 6
1834 bufs (nil) (0) flags 1030000 stream 000000 chan (nil) fd 21 thread 2
[27/Nov/2022:14:28:51][75236.7f975e039700][-conn:myserver:default:3:2121-] Debug(ns:driver): NsWriterQueue: writer
threads 2 nsend 61834 writersize 1024
[27/Nov/2022:14:28:51][75236.7f975e039700][-conn:myserver:default:3:2121-] Debug(ns:driver): ### Writer(22): add h
eader
[27/Nov/2022:14:28:51][75236.7f975e039700][-conn:myserver:default:3:2121-] Debug(request): headers:
:    HTTP/1.0 200 OK\x0d
:    Server: NaviServer/4.99.24\x0d
:    Date: Sun, 27 Nov 2022 22:28:51 GMT\x0d
:    Set-Cookie: ad_session_id=1206890001%2c0+%7b249+1669591731+951A4E03B6086CD4B81CEFA9844BBA62E226FA58%7d; Pa
th=/; Max-Age=3600\x0d
:    Last-Modified: Sun, 27 Nov 2022 22:28:51 GMT\x0d
:    Content-Type: application/pdf\x0d
:    Accept-Ranges: bytes\x0d
:    Content-Length: 61834\x0d
:    Connection: close\x0d
:    X-Frame-Options: SAMEORIGIN\x0d
:    X-Content-Type-Options: nosniff\x0d
:    X-XSS-Protection: 1; mode=block\x0d
:    Referrer-Policy: strict-origin\x0d
:
[27/Nov/2022:14:28:51][75236.7f975e039700][-conn:myserver:default:3:2121-] Debug(ns:driver): ### Writer(22) tosend
61834 files 0 bufsize 8192
[27/Nov/2022:14:28:51][75236.7f975e039700][-conn:myserver:default:3:2121-] Debug(ns:driver): NsWriterQueue NS_CONN
_SENT_VIA_WRITER connPtr 0x7f9778955110
[27/Nov/2022:14:28:51][75236.7f975e039700][-conn:myserver:default:3:2121-] Debug(ns:driver): NsWriterQueue NS_CONN
_SENT_VIA_WRITER connPtr 0x7f9778955110 clear sockPtr 0x7f973000f490
[27/Nov/2022:14:28:51][75236.7f975e039700][-conn:myserver:default:3:2121-] Debug(request): end GET /test/fs-downlo
ad HTTP/1.0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer poll collect 0x7f974c7a1a00
size 62312 streaming 0 rateLimit 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer final pollTimeout -1
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): Socket of pool '' is writable, writer l
imit 0 nsent 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer 0x7f974c7a1a00 can write to
client fd 9 (trigger 0) streaming 000000 size 62312 nsent 0 bufsize 478
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### WriterReadFromSpool [0]: fd 22 tose
nd 61834 files 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### WriterReadFromSpool 0x7f974c7a1a00
1030000 leftover 478 offset 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): Writer 0x7f974c7a1a00 continue OK (size
54120) => PUSH
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer poll collect 0x7f974c7a1a00
size 54120 streaming 0 rateLimit 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer final pollTimeout -1
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): Socket of pool '' is writable, writer l
imit 0 nsent 8192
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer 0x7f974c7a1a00 can write to
client fd 9 (trigger 0) streaming 000000 size 54120 nsent 8192 bufsize 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### WriterReadFromSpool [0]: fd 22 tose
nd 54120 files 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): Writer 0x7f974c7a1a00 continue OK (size
45928) => PUSH
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer poll collect 0x7f974c7a1a00
size 45928 streaming 0 rateLimit 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer final pollTimeout -1
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): Socket of pool '' is writable, writer l
imit 0 nsent 16384
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer 0x7f974c7a1a00 can write to client fd 9 (trigger 0) streaming 000000 size 45928 nsent 16384 bufsize 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### WriterReadFromSpool [0]: fd 22 tosend 45928 files 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): Writer 0x7f974c7a1a00 continue OK (size 37736) => PUSH
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer poll collect 0x7f974c7a1a00 size 37736 streaming 0 rateLimit 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer final pollTimeout -1
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): Socket of pool '' is writable, writer limit 0 nsent 24576
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer 0x7f974c7a1a00 can write to client fd 9 (trigger 0) streaming 000000 size 37736 nsent 24576 bufsize 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### WriterReadFromSpool [0]: fd 22 tosend 37736 files 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): Writer 0x7f974c7a1a00 continue OK (size 29544) => PUSH
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer poll collect 0x7f974c7a1a00 size 29544 streaming 0 rateLimit 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer final pollTimeout -1
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): Socket of pool '' is writable, writer limit 0 nsent 32768
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer 0x7f974c7a1a00 can write to client fd 9 (trigger 0) streaming 000000 size 29544 nsent 32768 bufsize 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### WriterReadFromSpool [0]: fd 22 tosend 29544 files 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): Writer 0x7f974c7a1a00 continue OK (size 21352) => PUSH
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer poll collect 0x7f974c7a1a00 size 21352 streaming 0 rateLimit 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer final pollTimeout -1
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): Socket of pool '' is writable, writer limit 0 nsent 40960
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer 0x7f974c7a1a00 can write to client fd 9 (trigger 0) streaming 000000 size 21352 nsent 40960 bufsize 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### WriterReadFromSpool [0]: fd 22 tosend 21352 files 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): Writer 0x7f974c7a1a00 continue OK (size 13160) => PUSH
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer poll collect 0x7f974c7a1a00 size 13160 streaming 0 rateLimit 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer final pollTimeout -1
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): Socket of pool '' is writable, writer limit 0 nsent 49152
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer 0x7f974c7a1a00 can write to client fd 9 (trigger 0) streaming 000000 size 13160 nsent 49152 bufsize 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### WriterReadFromSpool [0]: fd 22 tosend 13160 files 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): Writer 0x7f974c7a1a00 continue OK (size 4968) => PUSH
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer poll collect 0x7f974c7a1a00 size 4968 streaming 0 rateLimit 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer final pollTimeout -1
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): Socket of pool '' is writable, writer limit 0 nsent 57344
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer 0x7f974c7a1a00 can write to client fd 9 (trigger 0) streaming 000000 size 4968 nsent 57344 bufsize 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### WriterReadFromSpool [0]: fd 22 tosend 4968 files 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): Writer 0x7f974c7a1a00 done OK (size 0) => RELEASE
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): WriterSockRelease 0x7f974c7a1a00 refCount 0 keep 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): Writer: closed sock 9, file fd 22, error 0/0, sent=62312, flags=1030000
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): NsSockClose sockPtr 0x7f973000f490 (9) keep 0
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): NsSockClose calls RequestFree
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): === RequestFree cleans 0x7f973001e170 (avail 0 keep 0 length 0 contentLength 0)
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): RequestFree does not call Ns_ResetRequest on 0x7f973001e178
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): === Push request structure 0x7f973001e170 in (to pool)
[27/Nov/2022:14:28:51][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer final pollTimeout 30000
[27/Nov/2022:14:28:51][75236.7f973effd700][-driver:nssock:0-] Debug(ns:driver): === PollWait returned 1, trigger[0] 1
[27/Nov/2022:14:28:51][75236.7f973effd700][-driver:nssock:0-] Debug(ns:driver): SockRelease reason SOCK_CLOSE err 11 (sock -1)
[27/Nov/2022:14:28:51][75236.7f973effd700][-driver:nssock:0-] Debug(ns:driver): SockRelease bypasses SockClose, since we have an invalid socket
[27/Nov/2022:14:28:51][75236.7f973effd700][-driver:nssock:0-] Debug(ns:driver): DRIVER SockRelease: errno 11 drvPtr->closewait 2.000000
[27/Nov/2022:14:29:01][75236.7f973effd700][-driver:nssock:0-] Debug(ns:driver): === PollWait returned 0, trigger[0] 0
[27/Nov/2022:14:29:01][75236.7f973dffb700][-writer0-] Debug(ns:driver): ### Writer final pollTimeout 30000
[27/Nov/2022:14:29:11][75236.7f973effd700][-driver:nssock:0-] Debug(ns:driver): === PollWait returned 0, trigger[0] 0
[27/Nov/2022:14:29:21][75236.7f973effd700][-driver:nssock:0-] Debug(ns:driver): === PollWait returned 0, trigger[0] 0
[27/Nov/2022:14:29:21][75236.7f973e7fc700][-writer1-] Debug(ns:driver): ### Writer final pollTimeout 30000
By looking at the source code of nsoracle, i see that stream-writing code does not distinguish between binary and non-binary output.

Please try the following patch. If this helps and is sufficient, i will commit this (as mentioned in email, I have currently not Oracle environment at hand to test).

--- a/nsoracle.c
+++ b/nsoracle.c
@@ -4963,11 +4963,18 @@ stream_actually_write(int fd, Ns_Conn * conn, void *bufp, int length,

     if (to_conn_p) {
         struct iovec sbuf;
+        Ns_ReturnCode status;

         sbuf.iov_base = bufp;
         sbuf.iov_len = length;

- if (Ns_ConnWriteVChars(conn, &sbuf, 1, NS_CONN_STREAM) == NS_OK) { + if ((conn->flags & NS_CONN_WRITE_ENCODED) == 0u) { + status = Ns_ConnWriteVData(conn, &sbuf, 1, NS_CONN_STREAM); + } else { + status = Ns_ConnWriteVChars(conn, &sbuf, 1, NS_CONN_STREAM); + } + + if (status == NS_OK) { bytes_written = length; } else { bytes_written = 0;

The patch fixed the problem.

Thank you very much for your help.

Fixed applied to source ode repository at Bitbucket.