kokizzu / plv8js

Automatically exported from code.google.com/p/plv8js
Other
0 stars 0 forks source link

Corrupt plv8.elog() output in larger function. #78

Open GoogleCodeExporter opened 9 years ago

GoogleCodeExporter commented 9 years ago
I am getting corrupted output from plv8.elog. It is corrupted in both the 
console and the log file. For some reason, some lines will be cut off at the 
end and every time there will be corrupt data at the end of the line that 
appears to be funny symbols. It doesn't happen for every line either. For 
instance, in my current test, it happens on 1 out of 5 lines that are output to 
the screen. The output is inside a loop and so the same exact code is 
generating the output for each line. If I take that loop out and isolate it, it 
outputs fine.

The function I am building is 150+ lines including commenting and debug output. 
There are a number of cursors involved in loops, the deepest of which is 3 
levels deep. I have taken the text being output and passed it through 
JSON.stringify and new String() to filter any possible corruption in the string 
itself. Sometimes it doesn't change a thing, sometimes it changes which line 
gets corrupted.

I even took out some of the code and put it into another function that the main 
function calls. It just changed which line the corruption was happening. I have 
tested the lines which are garbled by executing them and they have worked, so 
that makes me believe only the output is being garbled. I would also have to 
say that the size and possibly the complexity of the function seems to be the 
big factor here. 

I also believe that the output isn't in sync with the processing of the 
function. I can't prove it yet, but it seems that the execution of function 
continues before the output is fully written out. I have had an instance where 
I tried to elog a JSON.stringify(obj) where the obj had a good number of items 
in it. Right after the output statement was the end of the function. It 
wouldn't output at all. So there might be a race condition or something that is 
leading to output corruption.

I'm not sure how to reproduce the problem. It seems almost to be random. It 
happens the same way every time I execute the function, but when I change the 
code in some way, it will happen differently, on a different line or even more 
or less lines.

What is the expected output? What do you see instead?

This is what I expect to see in the console.

NOTICE:  change:  
{"row":{"id":"c0292bf8-e591-11e2-a691-ab960767cae6","name_trans_id":"5f853440-e5
91-11e2-bcf1-6155568ef156","description_trans_id":"5f88ddc0-e591-11e2-bcf1-61555
68ef156","current_id":"654d9ca0-e591-11e2-87b0-bff28f6aafc9"},"table_name":"grad
ing_schemes","action_type":"INSERT"}

This is what actually appears in the console. There is another character after 
the @ symbol, but it doesn't display in the web. In the console it looks like a 
box with 4 numbers in it. 0 0 0 1, all in one of the corners of the box. It 
also appears the same in the log.

NOTICE:  change:  
{"row":{"id":"c0292bf8-e591-11e2-a691-ab960767cae6","name_trans_id":"5f853440-e5
91-11e2-bcf1-6155568ef156","description_trans_id":"5f88ddc0-e591-11e2-bcf1-61555
68ef156","current_id":"654d9ca0-e591-11e2-87b0-bff28f6aafc9"},"table_name":"grad
ing_schemes","action_type":"INS@

What version of the product are you using? On what operating system?
plv8 1.4.1 as installed by pgxn
libv8-3.8.9-20 as installed by Ubuntu
Postgresql 9.2
Ubuntu 12.10

Please provide any additional information below.

Original issue reported on code.google.com by haddow...@gmail.com on 5 Jul 2013 at 5:34

GoogleCodeExporter commented 9 years ago
What version of the product are you using? On what operating system?

plv8 1.4? Is there anything like plv8.version() method?
Postgres.app 9.3
OSX 10.7.5 (Lion) x64

Seeing this as well when logging large messages. My work around is to partition 
messages into 2000 bytes before logging. This large message logs correctly 
using plpgsql

    do language plpgsql $$
    BEGIN
        RAISE LOG '% %', repeat('A', 3000), 'x';
    END
    $$;

Original comment by mario.l....@gmail.com on 30 Dec 2013 at 5:14

GoogleCodeExporter commented 9 years ago
It appears that 512 is the max length of an allowed segment for elog. I have no 
idea why:

andrew=# do language plv8 $$ var repeat = function(it, n) { var res = ""; for 
(var i=0; i<n; i++) res += it; return res; };
        plv8.elog(NOTICE, repeat('A', 513), 'x');
   $$;
NOTICE:  
DO
andrew=# do language plv8 $$ var repeat = function(it, n) { var res = ""; for 
(var i=0; i<n; i++) res += it; return res; };
        plv8.elog(NOTICE, repeat('A', 512), 'x');
   $$;
NOTICE:  
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA x
DO
andrew=# 

Original comment by AMDuns...@gmail.com on 8 Sep 2014 at 9:09