08P01, 'invalid message format' about npgsql HOT 27 CLOSED

Some additional information:

The Npgsql version being used is 2.0.12.

The error still occus after replacing the LATIN9 version of the database with a UTF8 one.

On the application side, the error and the stack trace look like this:

Npgsql.NpgsqlException:
invalid message format
Severity: ERROR
Code: 08P01
at Npgsql.NpgsqlState.<ProcessBackendResponses_Ver_3>d__a.MoveNext()
at Npgsql.ForwardsOnlyDataReader.GetNextResponseObject()
at Npgsql.ForwardsOnlyDataReader.GetNextRowDescription()
at Npgsql.ForwardsOnlyDataReader.NextResult()
at Npgsql.ForwardsOnlyDataReader..ctor(IEnumerable`1 dataEnumeration, CommandBehavior behavior, NpgsqlCommand command, NotificationThreadBlock threadBlock, Boolean synchOnReadError)
at Npgsql.NpgsqlCommand.GetReader(CommandBehavior cb)
at Npgsql.NpgsqlCommand.ExecuteNonQuery()
...

I modified the function that produces the output rows, it now produces a single row, as follows:

create type udttappxmbtmp as
(
nlinha int4 ,
slinha text
);

create or replace function tappxmbtmpobterdeniiddth_setof( pniiddth int4, pnmododecomunicacao int4 ) returns udttappxmbtmp as
$$
-- 003.2014.03.20.11.34
-- pnmododecomunicacao 1=Teste, 2=Producao
declare
rdat record;
rout udttappxmbtmp;
sout text ;
begin
--
perform tappxmbtmppreencher( pniiddth, pnmododecomunicacao );
--
sout='';
for rdat in
select *
from tappxmbtmp
order by nlinha
loop
raise notice 'L=%, T=%', rdat.nlinha, rdat.slinha;
sout=sout || trim(rdat.slinha);
end loop;
--
rout.nlinha=1;
rout.slinha=sout;
--
return rout;
end;
$$
language plpgsql volatile security definer;

The error still occurs after this modification, meaning that the cardinality probably has no influence in the process that leads to the occurrence of error.

from npgsql.

Is it possible that you are sharing the connection to the database between multiple requests at the same time?

Npgsql, as other providers, isn't thread safe. NpgsqlConnection objects can't be shared between multiple threads.

from npgsql.

@heldermcvieira, is this issue still active? Both Postgresql 8.2 and Npgsql 2.0.12 are extremely old. If this issue is still a problem for you, can you please try and reproduce with a more modern setup? Otherwise let us know or close the issue.

from npgsql.

The issue is still there.
In the meantime, I made several modifications in the flow of the operations, to the point of creating NpgsqlConnection objects immediately before using them, and changed Npgsql to 2.1.0.
In the next two or three weeks I'll changed Npgsql to 2.2.0, but at this point I'd say the problem is probably restricted to PotsgreSQL 8.2, as I never saw this error with any other versions in the 8 or 9 series, using psqlODBC or Npgsql.
So, I'll now close the issue.

from npgsql.

This is really strange, @heldermcvieira . My first bet was the possibility that you were using the same connection concurrently, but as you said you created NpgsqlConnection objects before using them, then this possibility is discarded.

Please, let us know how your migration to 2.2.0 goes.

Thanks in advance.

from npgsql.

I am getting this error using v2.2.3.0, but it only seems to happen with huge requests (e.g. 700KB+). The strange thing is that I have integration tests that run against the database using NUnit that work just fine, but as soon as my Web API tries to do the exact same thing (same inputs and everything) I get this error. My DbContext is injected using Ninject InRequestScope, so I'm pretty sure concurrency shouldn't be an issue here.

Any ideas?

from npgsql.

Any possibility you can create a network log on the tcp packets, such as using Wireshark that has built-in support for identifying postgresql messages?

from npgsql.

I upgraded the PostgreSQL server to 9.3.5 and Npgsql 2.2.0.0, and the problem didn't go away.
So, I set the log level to DEBUG5 and the result is quite different from what I expected...

Previously, I thought that the error was raised at the end of the command "select tappxmbtmpobterdeniiddth(...)".

In fact, now I guess the error is raised at the end of the next command sent to the server, which is always "select * from tsyssql where ckeysql='TAPPDTCInserirNIIDDTH';", apparently at the point where the result data is being encoded to be sent back to the client ( the result of "select * from tsyssql where ckeysql='TAPPDTCInserirNIIDDTH';" is a constant string expression, which is "select tappdtcinserirniiddth( {01}::int4, {02}::text, {03}::text, {04}::int4 );" ).

I also noticed the frequent appearance of "mapped win32 error code 2 to 2" debug messages in the vicinity of the offending sequence of events.

I extracted a sample from a log file, as follows.
To respect customer privacy, I cut a few lines of text around line # 122 of the sample, and marked the gap with "(...)".
The error appears in line # 161 of the sample, and I ended at line # 186, as the rest seems to be related with post-mortem housekeeping, so to speak.

[START OF SAMPLE]
2014-12-11 10:09:09 GMT DEBUG: 00000: StartTransactionCommand
2014-12-11 10:09:09 GMT LOCATION: start_xact_command, src\backend\tcop\postgres.c:2385
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT DEBUG: 00000: StartTransaction
2014-12-11 10:09:09 GMT LOCATION: ShowTransactionState, src\backend\access\transam\xact.c:4469
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT DEBUG: 00000: name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
2014-12-11 10:09:09 GMT LOCATION: ShowTransactionStateRec, src\backend\access\transam\xact.c:4507
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT DEBUG: 00000: mapped win32 error code 2 to 2
2014-12-11 10:09:09 GMT CONTEXT: SQL statement "truncate tappxmbtmp"
PL/pgSQL function tappxmbtmppreencher(integer,integer) line 8 at SQL statement
SQL statement "SELECT tappxmbtmppreencher( pniiddth, pnmododecomunicacao )"
PL/pgSQL function tappxmbtmpobterdeniiddth(integer,integer) line 9 at PERFORM
2014-12-11 10:09:09 GMT LOCATION: _dosmaperr, src\port\win32error.c:187
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT DEBUG: 00000: mapped win32 error code 2 to 2
2014-12-11 10:09:09 GMT CONTEXT: SQL statement "truncate tappxmbtmp"
PL/pgSQL function tappxmbtmppreencher(integer,integer) line 8 at SQL statement
SQL statement "SELECT tappxmbtmppreencher( pniiddth, pnmododecomunicacao )"
PL/pgSQL function tappxmbtmpobterdeniiddth(integer,integer) line 9 at PERFORM
2014-12-11 10:09:09 GMT LOCATION: _dosmaperr, src\port\win32error.c:187
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT DEBUG: 00000: mapped win32 error code 2 to 2
2014-12-11 10:09:09 GMT CONTEXT: SQL statement "truncate tappxmbtmp"
PL/pgSQL function tappxmbtmppreencher(integer,integer) line 8 at SQL statement
SQL statement "SELECT tappxmbtmppreencher( pniiddth, pnmododecomunicacao )"
PL/pgSQL function tappxmbtmpobterdeniiddth(integer,integer) line 9 at PERFORM
2014-12-11 10:09:09 GMT LOCATION: _dosmaperr, src\port\win32error.c:187
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT DEBUG: 00000: building index "tappxmbtmp_pk" on table "tappxmbtmp"
2014-12-11 10:09:09 GMT CONTEXT: SQL statement "truncate tappxmbtmp"
PL/pgSQL function tappxmbtmppreencher(integer,integer) line 8 at SQL statement
SQL statement "SELECT tappxmbtmppreencher( pniiddth, pnmododecomunicacao )"
PL/pgSQL function tappxmbtmpobterdeniiddth(integer,integer) line 9 at PERFORM
2014-12-11 10:09:09 GMT LOCATION: index_build, src\backend\catalog\index.c:1976
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT DEBUG: 00000: mapped win32 error code 2 to 2
2014-12-11 10:09:09 GMT CONTEXT: SQL statement "truncate tappxmbtmp"
PL/pgSQL function tappxmbtmppreencher(integer,integer) line 8 at SQL statement
SQL statement "SELECT tappxmbtmppreencher( pniiddth, pnmododecomunicacao )"
PL/pgSQL function tappxmbtmpobterdeniiddth(integer,integer) line 9 at PERFORM
2014-12-11 10:09:09 GMT LOCATION: _dosmaperr, src\port\win32error.c:187
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT DEBUG: 00000: mapped win32 error code 2 to 2
2014-12-11 10:09:09 GMT CONTEXT: SQL statement "truncate tappxmbtmp"
PL/pgSQL function tappxmbtmppreencher(integer,integer) line 8 at SQL statement
SQL statement "SELECT tappxmbtmppreencher( pniiddth, pnmododecomunicacao )"
PL/pgSQL function tappxmbtmpobterdeniiddth(integer,integer) line 9 at PERFORM
2014-12-11 10:09:09 GMT LOCATION: _dosmaperr, src\port\win32error.c:187
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT DEBUG: 00000: building index "pg_toast_329486_index" on table "pg_toast_329486"
2014-12-11 10:09:09 GMT CONTEXT: SQL statement "truncate tappxmbtmp"
PL/pgSQL function tappxmbtmppreencher(integer,integer) line 8 at SQL statement
SQL statement "SELECT tappxmbtmppreencher( pniiddth, pnmododecomunicacao )"
PL/pgSQL function tappxmbtmpobterdeniiddth(integer,integer) line 9 at PERFORM
2014-12-11 10:09:09 GMT LOCATION: index_build, src\backend\catalog\index.c:1976
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT DEBUG: 00000: mapped win32 error code 2 to 2
2014-12-11 10:09:09 GMT CONTEXT: SQL statement "truncate tappxmbtmp"
PL/pgSQL function tappxmbtmppreencher(integer,integer) line 8 at SQL statement
SQL statement "SELECT tappxmbtmppreencher( pniiddth, pnmododecomunicacao )"
PL/pgSQL function tappxmbtmpobterdeniiddth(integer,integer) line 9 at PERFORM
2014-12-11 10:09:09 GMT LOCATION: _dosmaperr, src\port\win32error.c:187
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT DEBUG: 00000: analyzing "pg_temp_6.tappxmbtmp"
2014-12-11 10:09:09 GMT CONTEXT: SQL statement "analyze tappxmbtmp"
PL/pgSQL function tappxmbtmppreencher(integer,integer) line 9 at SQL statement
SQL statement "SELECT tappxmbtmppreencher( pniiddth, pnmododecomunicacao )"
PL/pgSQL function tappxmbtmpobterdeniiddth(integer,integer) line 9 at PERFORM
2014-12-11 10:09:09 GMT LOCATION: do_analyze_rel, src\backend\commands\analyze.c:335
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT DEBUG: 00000: "tappxmbtmp": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
2014-12-11 10:09:09 GMT CONTEXT: SQL statement "analyze tappxmbtmp"
PL/pgSQL function tappxmbtmppreencher(integer,integer) line 9 at SQL statement
SQL statement "SELECT tappxmbtmppreencher( pniiddth, pnmododecomunicacao )"
PL/pgSQL function tappxmbtmpobterdeniiddth(integer,integer) line 9 at PERFORM
2014-12-11 10:09:09 GMT LOCATION: acquire_sample_rows, src\backend\commands\analyze.c:1299
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT DEBUG: 00000: mapped win32 error code 2 to 2
2014-12-11 10:09:09 GMT CONTEXT: SQL statement "analyze tappxmbtmp"
PL/pgSQL function tappxmbtmppreencher(integer,integer) line 9 at SQL statement
SQL statement "SELECT tappxmbtmppreencher( pniiddth, pnmododecomunicacao )"
PL/pgSQL function tappxmbtmpobterdeniiddth(integer,integer) line 9 at PERFORM
2014-12-11 10:09:09 GMT LOCATION: _dosmaperr, src\port\win32error.c:187
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT DEBUG: 00000: mapped win32 error code 2 to 2
2014-12-11 10:09:09 GMT CONTEXT: SQL statement "insert into tappxmbtmp ( nlinha , slinha )

      values                 ( nextval('tappxmbtmp_nlinha_seq'), pslinha )"
PL/pgSQL function tappxmbtmpadicionarlinha(text) line 5 at SQL statement
SQL statement "SELECT tappxmbtmpadicionarlinha( '<soapenv:Body>' )"
PL/pgSQL function tappxmbtmppreencher(integer,integer) line 18 at PERFORM
SQL statement "SELECT tappxmbtmppreencher( pniiddth, pnmododecomunicacao )"
PL/pgSQL function tappxmbtmpobterdeniiddth(integer,integer) line 9 at PERFORM

2014-12-11 10:09:09 GMT LOCATION: _dosmaperr, src\port\win32error.c:187
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT DEBUG: 00000: mapped win32 error code 2 to 2
2014-12-11 10:09:09 GMT CONTEXT: SQL statement "insert into tappxmbtmp ( nlinha , slinha )

      values                 ( nextval('tappxmbtmp_nlinha_seq'), pslinha )"
PL/pgSQL function tappxmbtmpadicionarlinha(text) line 5 at SQL statement
SQL statement "SELECT tappxmbtmpadicionarlinha( '<soapenv:Body>' )"
PL/pgSQL function tappxmbtmppreencher(integer,integer) line 18 at PERFORM
SQL statement "SELECT tappxmbtmppreencher( pniiddth, pnmododecomunicacao )"
PL/pgSQL function tappxmbtmpobterdeniiddth(integer,integer) line 9 at PERFORM

2014-12-11 10:09:09 GMT LOCATION: _dosmaperr, src\port\win32error.c:187
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT DEBUG: 00000: cache_locale_time() executed; locale: "Portuguese_Portugal.1252"
2014-12-11 10:09:09 GMT CONTEXT: SQL statement "SELECT tappxmbtmpadicionarlinha( tappxmbtmpenquadrarelemento( 'MovementDate' , to_char(rdat.ddatdth,'YYYY-MM-DD') ))"
PL/pgSQL function tappxmbtmppreenchercpgappa(integer,integer) line 40 at PERFORM
SQL statement "SELECT tappxmbtmppreenchercpgappa( pniiddth, pnmododecomunicacao )"
PL/pgSQL function tappxmbtmppreencher(integer,integer) line 35 at PERFORM
SQL statement "SELECT tappxmbtmppreencher( pniiddth, pnmododecomunicacao )"
PL/pgSQL function tappxmbtmpobterdeniiddth(integer,integer) line 9 at PERFORM
2014-12-11 10:09:09 GMT LOCATION: cache_locale_time, src\backend\utils\adt\pg_locale.c:627
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT NOTICE: 00000: L=1451349, T=soapenv:Body
2014-12-11 10:09:09 GMT LOCATION: exec_stmt_raise, src\pl\plpgsql\src\pl_exec.c:3041
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT NOTICE: 00000: L=1451350, T=<doc:registerFarmersPurchasePartialDocRequestElem xmlns:doc='https://servicos.portaldasfinancas.gov.pt/sgdtws/GuiasAquisicaoProdAgricola/'>
2014-12-11 10:09:09 GMT LOCATION: exec_stmt_raise, src\pl\plpgsql\src\pl_exec.c:3041
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
(...)
2014-12-11 10:09:09 GMT LOCATION: exec_stmt_raise, src\pl\plpgsql\src\pl_exec.c:3041
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT NOTICE: 00000: L=1451388, T=
2014-12-11 10:09:09 GMT LOCATION: exec_stmt_raise, src\pl\plpgsql\src\pl_exec.c:3041
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT NOTICE: 00000: L=1451389, T=/doc:registerFarmersPurchasePartialDocRequestElem
2014-12-11 10:09:09 GMT LOCATION: exec_stmt_raise, src\pl\plpgsql\src\pl_exec.c:3041
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT NOTICE: 00000: L=1451390, T=/soapenv:Body
2014-12-11 10:09:09 GMT LOCATION: exec_stmt_raise, src\pl\plpgsql\src\pl_exec.c:3041
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT DEBUG: 00000: CommitTransactionCommand
2014-12-11 10:09:09 GMT LOCATION: finish_xact_command, src\backend\tcop\postgres.c:2409
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT DEBUG: 00000: CommitTransaction
2014-12-11 10:09:09 GMT LOCATION: ShowTransactionState, src\backend\access\transam\xact.c:4469
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:09 GMT DEBUG: 00000: name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 54836/1/48, nestlvl: 1, children:
2014-12-11 10:09:09 GMT LOCATION: ShowTransactionStateRec, src\backend\access\transam\xact.c:4507
2014-12-11 10:09:09 GMT STATEMENT: select tappxmbtmpobterdeniiddth( 42050::int4, 2::int4 ) as slinha;
2014-12-11 10:09:10 GMT DEBUG: 00000: StartTransactionCommand
2014-12-11 10:09:10 GMT LOCATION: start_xact_command, src\backend\tcop\postgres.c:2385
2014-12-11 10:09:10 GMT STATEMENT: select * from tsyssql where ckeysql='TAPPDTCInserirNIIDDTH';
2014-12-11 10:09:10 GMT DEBUG: 00000: StartTransaction
2014-12-11 10:09:10 GMT LOCATION: ShowTransactionState, src\backend\access\transam\xact.c:4469
2014-12-11 10:09:10 GMT STATEMENT: select * from tsyssql where ckeysql='TAPPDTCInserirNIIDDTH';
2014-12-11 10:09:10 GMT DEBUG: 00000: name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
2014-12-11 10:09:10 GMT LOCATION: ShowTransactionStateRec, src\backend\access\transam\xact.c:4507
2014-12-11 10:09:10 GMT STATEMENT: select * from tsyssql where ckeysql='TAPPDTCInserirNIIDDTH';
2014-12-11 10:09:10 GMT DEBUG: 00000: CommitTransactionCommand
2014-12-11 10:09:10 GMT LOCATION: finish_xact_command, src\backend\tcop\postgres.c:2409
2014-12-11 10:09:10 GMT STATEMENT: select * from tsyssql where ckeysql='TAPPDTCInserirNIIDDTH';
2014-12-11 10:09:10 GMT DEBUG: 00000: CommitTransaction
2014-12-11 10:09:10 GMT LOCATION: ShowTransactionState, src\backend\access\transam\xact.c:4469
2014-12-11 10:09:10 GMT STATEMENT: select * from tsyssql where ckeysql='TAPPDTCInserirNIIDDTH';
2014-12-11 10:09:10 GMT DEBUG: 00000: name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
2014-12-11 10:09:10 GMT LOCATION: ShowTransactionStateRec, src\backend\access\transam\xact.c:4507
2014-12-11 10:09:10 GMT STATEMENT: select * from tsyssql where ckeysql='TAPPDTCInserirNIIDDTH';
2014-12-11 10:09:10 GMT ERROR: 08P01: invalid message format
2014-12-11 10:09:10 GMT LOCATION: pq_getmsgend, src\backend\libpq\pqformat.c:652
2014-12-11 10:09:11 GMT DEBUG: 00000: shmem_exit(0): 7 callbacks to make
2014-12-11 10:09:11 GMT LOCATION: shmem_exit, src\backend\storage\ipc\ipc.c:212
2014-12-11 10:09:11 GMT DEBUG: 00000: proc_exit(0): 3 callbacks to make
2014-12-11 10:09:11 GMT LOCATION: proc_exit_prepare, src\backend\storage\ipc\ipc.c:184
2014-12-11 10:09:11 GMT DEBUG: 00000: exit(0)
2014-12-11 10:09:11 GMT LOCATION: proc_exit, src\backend\storage\ipc\ipc.c:135
2014-12-11 10:09:11 GMT DEBUG: 00000: shmem_exit(-1): 0 callbacks to make
2014-12-11 10:09:11 GMT LOCATION: shmem_exit, src\backend\storage\ipc\ipc.c:212
2014-12-11 10:09:11 GMT DEBUG: 00000: proc_exit(-1): 0 callbacks to make
2014-12-11 10:09:11 GMT LOCATION: proc_exit_prepare, src\backend\storage\ipc\ipc.c:184
2014-12-11 10:09:11 GMT DEBUG: 00000: shmem_exit(0): 8 callbacks to make
2014-12-11 10:09:11 GMT LOCATION: shmem_exit, src\backend\storage\ipc\ipc.c:212
2014-12-11 10:09:11 GMT DEBUG: 00000: StartTransaction
2014-12-11 10:09:11 GMT LOCATION: ShowTransactionState, src\backend\access\transam\xact.c:4469
2014-12-11 10:09:11 GMT DEBUG: 00000: name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
2014-12-11 10:09:11 GMT LOCATION: ShowTransactionStateRec, src\backend\access\transam\xact.c:4507
2014-12-11 10:09:11 GMT DEBUG: 00000: drop auto-cascades to constraint tsysobjarvoretmp_pk on table tsysobjarvoretmp
2014-12-11 10:09:11 GMT LOCATION: reportDependentObjects, src\backend\catalog\dependency.c:907
2014-12-11 10:09:11 GMT DEBUG: 00000: drop auto-cascades to index tsysobjarvoretmp_pk
2014-12-11 10:09:11 GMT LOCATION: reportDependentObjects, src\backend\catalog\dependency.c:907
2014-12-11 10:09:11 GMT DEBUG: 00000: drop auto-cascades to type tsysobjarvoretmp
2014-12-11 10:09:11 GMT LOCATION: reportDependentObjects, src\backend\catalog\dependency.c:907
2014-12-11 10:09:11 GMT DEBUG: 00000: drop auto-cascades to type tsysobjarvoretmp
[END OF SAMPLE]

from npgsql.

It seems that the sample text is not correctly represented in the comment I just posted.
In some lines, the "NOTICE: 00000: L=nnn, T= xxx" representation is being cut after the "T=".
They're all parts of a SOAP body, so...

from npgsql.

@Emill I have a packet capture for you. Where should I send it?

from npgsql.

Upload to google drive or something?
Den 13 dec 2014 02:17 skrev "Matthew Baker" [email protected]:

@Emill https://github.com/Emill I have a packet capture for you. Where
should I send it?

—
Reply to this email directly or view it on GitHub
#189 (comment).

from npgsql.

@Emill https://www.dropbox.com/s/jph8pe9nxzj7zzv/failedquery.pcap?dl=0

from npgsql.

@Emill any update on this?

from npgsql.

Digging more deeply into this in NpgsqlCommand.PrepareExecute.cs, internal ForwardsOnlyDataReader GetReader(CommandBehavior cb) the call to GetCommandText(), which calls GetCommandText(false) which calls AppendCommandReplacingParameterValues and then finally calls commandBuilder.ToArray().

When I take the verbatim SQL statement generated on this code path ( and drop it into Navicat I get the following error:

ERROR:  invalid byte sequence for encoding "UTF8": 0x00

And when I look at the result of commandBuilder.ToArray() I notice that it is adding hundreds of \0 to the end of my statement.

UPDATE "public"."table" SET "xml"=E'<?xml version=\"1.0\" encoding=\"UTF-8\"?>\r<lots><of><xml>\r\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0..........' WHERE "id" = 'bffdab98-caf3-4c6a-8621-b9063fd72079'

With a breakpoint where ToArray() is called I ran an Immediate on the result of that call an encoded it into a UTF8 string, where I confirmed that the extra null terminators were in there. In the Immediate Window I output the result of commandBuilder.ToArray() and got something like this:

[94]: 13
[95]: 32
[96]: 32
[97]: 60
[98]: 68
[99]: 105
< More... (The first 100 of 1310814 items were displayed.) >

Looking at the last item in the array I would expect a null terminator, but it actually isn't

commandBuilder.ToArray()[1310813]
39

It looks like you address this in the public NpgsqlQuery(byte[] command) constructor, and the pgCommandBytes that ultimately get written onto the wire in NpgsqlQuery.WriteToStream(Stream outputStream) DO end in a null terminator. The PCAP file I have above shows the bytes going out onto the wire in 1500 byte chunks, and then eventually getting this back from Postgres:

Code: 08P01
Message: invalid message format

I don't see anything in the last packet that is out of the ordinary...It does look like Postgres doesn't ACK TCP segments as they come across, but maybe that is expected behavior.

from npgsql.

@heldermcvieira could you reopen this? It's definitely still an issue and I can't reopen it myself.

from npgsql.

Hi, @mlb5000 !

Are you setting a size to the string parameter which holds your xml text?

Also, you said that when you use your Web API is that the problem occurs. Your web api host is the same host your nunit tests run? Is it possible that your web api is using a different version of Npgsql? Maybe one in GAC?

from npgsql.

@franciscojunior I don't believe they run in the same host. Web API runs in its own thing and the unit tests run in the ReSharper unit test host.

Both the Web API project and the unit test project are using Npgsql version 2.2.3.0 from Nuget, though there is a version of the library in the GAC from installing Postgresql (v2.0.14.3). I'm going to uninstall it and see if that fixes anything.

from npgsql.

@franciscojunior nope, same error after uninstalling the GAC version.

from npgsql.

Also @franciscojunior I assume by

"Are you setting a size to the string parameter which holds your xml text?"

that you mean in the database column? If so, there is no limit, it's just a text column.

from npgsql.

@franciscojunior ok wow, I don't know what the distinction is, but the following fixed the issue. Changing stream.GetBuffer() to stream.ToArray():

    var postedFile = request.Files[0];
    var stream = new MemoryStream();
    postedFile.InputStream.CopyTo(stream);
    var input = _processor.PersistInput(System.Text.Encoding.UTF8.GetString(stream.ToArray()),
            DateTime.Parse(request.Form.Get("inputDate")));

It might still be an issue in Npgsql, but you might have a lead on how to fix it/isolate this problem now.

from npgsql.

Basically, if the string value we try to persist using Npgsql was derived from MemoryStream.GetBuffer() it will explode, but if it came from MemoryStream.ToArray() it will work fine.

from npgsql.

that you mean in the database column? If so, there is no limit, it's just a text column

No, I meant the NpgsqlParameter which would hold the xml value. In your code.

@franciscojunior ok wow, I don't know what the distinction is, but the following fixed the issue. Changing stream.GetBuffer() to stream.ToArray():

As I suspected, the msdn documentation tells the difference, which explains why it fixed your problem:
"Note that the buffer contains allocated bytes which might be unused. For example, if the string "test" is written into the MemoryStream object, the length of the buffer returned from GetBuffer is 256, not 4, with 252 bytes unused. To obtain only the data in the buffer, use the ToArray method; however, ToArray creates a copy of the data in memory."

The ToArray() returns only the string. Npgsql is supposed to work only with a valid string. I think we don't have tests for Npgsql where a long string has a lot of null bytes. We may currently have some problems in the way of sending data with null values. We would need to create some tests for this case to test it out.

from npgsql.

👍 thanks for your help guys

from npgsql.

Thank you too for your feedback, @mlb5000 .
I'm glad to hear you are being able to get Npgsql working again in your production host.

from npgsql.

Hi, @heldermcvieira !

Are you still having the problem described in this issue? If so, please, let us know which errors you are getting. If not, please, close the issue again.

Thanks in advance.

from npgsql.

Yes, as described above.
However, I reopened the issue because mlb5000 asked me to do so. But reading the thread it seems his problem is solved, so I'll close it again, as I'm now quite convinced that my issue is restricted to the server and probably isn't caused by the interaction with Npgsql.

from npgsql.

Yes, as described above.
However, I reopened the issue because mlb5000 asked me to do so. But reading the thread it seems his problem is solved, so I'll close it again, as I'm now quite convinced that my issue is restricted to the server and probably isn't caused by the interaction with Npgsql.

Great! Thanks for your reply.
I hope your problem isn't related to Npgsql, but if you find it is indeed a problem in Npgsql, please reopen the issue.

Thanks again for your feedback.

from npgsql.