Issue Details (XML | Word | Printable)

Key: CORE-2493
Type: Improvement Improvement
Status: Resolved Resolved
Resolution: Fixed
Priority: Minor Minor
Assignee: Vlad Khorsun
Reporter: John Kilin
Votes: 15
Watchers: 11
Operations

If you were logged in you would be able to see more operations.
Firebird Core

Append the IP address of the remote host to error messages in firebird.log for TCP connections

Created: 03/Jun/09 12:19 PM   Updated: 16/Feb/18 10:07 PM
Component/s: Engine
Affects Version/s: None
Fix Version/s: 3.0 RC2, 2.5.9

QA Status: Done with caveats
Test Details:
Test verifies that only ONE of pair messages is really added to firebird.log - 10053.

It seems that it is unable to implement test which will lead to appearance of 10054 because in such case engine keeps DB file opened after killing launched ISQL process which is done ES/EDS.
When this file has name = "initial" ('bugs.core_2493.fdb") then fb_test will raise exception on cleanup phase. Otherwise one can not to remove this (new) .fdb-file when test is finished.
It seems that DB file is kept opened such too long time only under fb_test env., so I will investigate this later.




 All   Comments   Change History   Subversion Commits      Sort Order: Ascending order - Click to sort in descending order
kdv added a comment - 04/Mar/10 08:35 AM
I wan to raise interest to this, because Interbase already have things like that:

IBASE (Server) Sat Mar 10 18:56:02 2007
INET/inet_error: send errno = 10054 client host = IBASE connection name = ibase user name = ADMIN server port number = 3050

Dmitry Yemanov added a comment - 16/Dec/10 10:34 AM - edited
I'm thinking about the following change in the output.

Now:

INET/inet_error: read errno = 10054

To be:

INET error in routine "read", errno = 10054
Unable to complete network request to host "client".
Error reading data from the connection.
An existing connection was forcibly closed by the remote host

Does it look suitable? Or perhaps it's too much verbose?

Dmitry Yemanov added a comment - 16/Dec/10 01:22 PM
A shorter alternative:

INET error in routine "read", errno = 10054 (An existing connection was forcibly closed by the remote host)
Protocol: TCPv4, remote host: 123.123.123.123, process: 3200 (C:\Tools\IBExpert\IBExpert.exe)

Philippe Makowski added a comment - 16/Dec/10 01:35 PM
I like the last one (A shorter alternative)

Simonov Denis added a comment - 09/Jul/12 04:29 AM
Whether it is impossible to add this improvement in 2.5.2?

Dmitry Yemanov added a comment - 09/Jul/12 04:46 AM
Not for 2.5.2 for sure.

Simonov Denis added a comment - 23/Oct/12 09:23 AM
Add there a line of connection
localhost:mydatabase or at least alias DB

Dmitry Yemanov added a comment - 23/Oct/12 09:40 AM
I doubt this is possible in general, as the network layer is isolated from the engine. Theoretically, a database pathname / alias could be gathered from the op_attach packet and stored for the reporting purposes, but surely not the host name. Also, what db info to report if the network error happens with the listener socket in SS/SC? It multiplexes all the connections, so it seems impossible to report a db info properly. So I tend to reject this idea.

Simonov Denis added a comment - 23/Oct/12 09:59 AM
In principle I agree. The purpose of this message to clarify a problem with communication links with computers of clients. It is for this purpose optional to know a name DB.

Jesus Angel Garcia Zarco added a comment - 21/Jun/13 11:33 AM
If it is feasible, backport to version 2.5.X the information that is posible to record.

Dmitry Yemanov added a comment - 23/Nov/14 09:30 AM
I'm about to commit the simplest solution, based on the already available information in the remote subsystem.
Depending on situation, the output would look like:

// No connection was established
solaris Sun Nov 23 11:59:23 2014
INET error in routine "bind" (errno = 98)

// Established connection (client-side)
solaris Sun Nov 23 11:59:23 2014
INET error in routine "send" (errno = 32), server host: solaris

// Established connection (server-side)
solaris Sun Nov 23 11:59:23 2014
INET (TCPv4) error in routine "read" (errno = 104), client host: solaris (127.0.0.1), user: dimitr

Would it be acceptable for v3? Later we could add more context information, if required.

Simonov Denis added a comment - 23/Nov/14 11:54 AM
This is the right decision not to delay the release of Fb3. The only caveat - the original version of your proposed text of the error message was more detailed (I do not take parameters, only the text itself).

Dmitry Yemanov added a comment - 23/Nov/14 12:01 PM
The "original version" was taken from the top of my head, the latest one is based on the existing code. We could translate network error codes into text, but I'm not sure we should (everyone can google). We could add client process info for server-side messages, but it requires more coding.

Vlad Khorsun added a comment - 10/Jan/16 11:11 PM
Log message now looks like

INET/inet_error: <routine_name> errno = <error_number> [, <peer_Info>] [, <user_info>]

where

<peer_Info> ::=
   <peer_kind> host = <peer_name>
   <peer_kind> address = <peer_address>
   <peer_kind> host = <peer_name> , address = <peer_address>

<user_info> ::=
  user = <user_name>

<peer_kind> ::= [aux] client|server

[aux] client|server - kind of connection with peer:
- optional prefix "aux" means port used for events processing
- client - error reported by server side and peer is client
- server - error reported by client side and peer is server

<peer_name> - name of the peer host:
- client reports server name specified at conneciton string
- server reports client name passed by client in connection request packet

<peer_address> - IP address and port reported by getnameinfo() API function
it look depends on actual protocol (TCPv4 or TCPv6) used by connection.

<user_name> - authenticated Firebird login name, coupd be reported by server side
after successful authorization only

Examples:
a) server detect abnormal disconnect of client
INET/inet_error: read errno = 10054, client host = win7x64, address = ::1/51490, user = vlad
INET/inet_error: read errno = 10054, aux client host = win7x64, address = ::1/51500

b) client detect abnormal disconnect
INET/inet_error: read errno = 10053, server host = localhost, address = ::1/3050
INET/inet_error: read errno = 10054, aux server host = localhost, address = ::1/52286

Pavel Zotov added a comment - 12/Jan/16 06:37 AM
I could reproduce 10053 using this scenario:

isql-1:
#####
SQL> recreate table test1(s1 varchar(250) unique, s2 varchar(250) unique, s3 varchar(250) unique);
SQL> commit;
SQL> set term ;^
SQL> set term ^;
SQL> execute block as
CON> declare stt varchar(512);
CON> begin
CON> stt='insert into test1 select c,c,c from (select rpad('''', 250, uuid_to_char(gen_uuid())) as c from rdb$types a,rdb$types b, rd
b$types c)';
CON> execute statement (stt)
CON> on external 'localhost:' || rdb$get_context('SYSTEM','DB_NAME')
CON> as user 'SYSDBA' password 'masterke';
CON>
CON> end
CON> ^

isql-2:
#####
echo delete from mon$attachments; | isql /3329:e30

isql-1:
#####
Statement failed, SQLSTATE = 42000
Execute statement error at isc_dsql_execute2 :
335544794 : operation was cancelled

firebird.log:
#########

CSPROG Tue Jan 12 09:21:32 2016
INET/inet_error: send errno = 10053, server host = localhost, address = 127.0.0.1/3329

NOTE: message "SEND errno = 10053" was added, not "READ errno = 10053" (as you've wrote).

Is this result expected ? Can message "read errno = 10053, server host ..." be reproduced by some other way, not using ES / EDS ?

PS.

Message: INET/inet_error: read errno = 10054, client host = ..., address = ..., user = ... - does appear in firebird.log when either ISQL process is forcely kiled (by pskill et al) or its window is closed or by pressing Ctrl-Break inside ISQL when it idle or does something;

But this message (and none at all) do NOT appear when either ISQL session is closed due to gfix -shut full -force 0, or because of delete from mon$attachments.
Is it correct ?

Vlad Khorsun added a comment - 12/Jan/16 09:39 AM
> Is this result expected ?
Yes

> Can message "read errno = 10053, server host ..." be reproduced by some other way, not using ES / EDS ?
Yes
But why do you need exactly this message ?

> Is it correct ?
Yes

Pavel Zotov added a comment - 12/Jan/16 09:47 AM
>> Can message "read errno = 10053, server host ..." be reproduced by some other way, not using ES / EDS ?
>Yes

Can you please tell me what's this ? (I mean that it should differ from ES/EDS)

>But why do you need exactly this message ?

Just for making new .fbt that will be useful (IMO) for this ticket.

Vlad Khorsun added a comment - 12/Jan/16 09:57 AM
>>> Can message "read errno = 10053, server host ..." be reproduced by some other way, not using ES / EDS ?
>>Yes
>
>Can you please tell me what's this ? (I mean that it should differ from ES/EDS)

read error could happen when ... read return error (aborted, for example).
The most easy way to simulate read error at client is to start long running query and kill the server while client waiting for result.

> Just for making new .fbt that will be useful (IMO) for this ticket.

I still don't understand how *failed operation name* is related with this ticket (which is about reporting *peer name\address*)

Pavel Zotov added a comment - 12/Jan/16 10:09 AM
> I still don't understand how *failed operation name* is related with this ticket (which is about reporting *peer name\address*)

I'm not interested about OPERATION that failed; the only what's matter - content of firebird.log and parsing 10054 & 10053 lines :-)

In the post 10/Jan/16 11:11 PM you've wrote that firebird.log can contain message:
===
b) client detect abnormal disconnect
INET/inet_error: read errno = 10053, server host = localhost, address = ::1/3050
===

I tried to reproduce this and found that word "READ" was replaced with "SEND".
So, for test one need to be ready that (for error 10053) some other word can occur at the token pos #3 ? ( "read", "send", .. what else ?)

Dmitry Yemanov added a comment - 12/Jan/16 10:21 AM
Better ignore everything between "inet_error:" and "errno" tokens.

Pavel Zotov added a comment - 12/Jan/16 08:33 PM
echo set list on; ^
  select mon$remote_address ^
  from mon$attachments where mon$attachment_id=current_connection; ^
  select count(*) from rdb$types,rdb$types,rdb$types; | isql localhost/3333:e30

MON$REMOTE_ADDRESS fe80::c40e:21ec:b5c7:8963%3/56831

-- then it hangs and we terminate it by pressing Ctrl-Break ---

type firebird.log

INET/inet_error: read errno = 10054, client host = oksana, address = fe80::c40e:21ec:b5c7:8963/56831, user = oksana1


NOTE: percent sign present when returning from mon$attachments and absent when data are written into fb.log.
8963%3/56831
vs
8963/56831

Why ?

Vlad Khorsun added a comment - 13/Jan/16 09:40 AM
Because printf is crazy, when have format specifier with no arguments.

Docs: The results are undefined if there are not enough arguments for all the format specifications.

Fixed.

Vlad Khorsun added a comment - 14/Feb/18 12:57 PM
Backported into v2.5.9

Pavel Zotov added a comment - 16/Feb/18 10:07 PM
Message in firebird.log slightly differ in 2.5.9 vs 3.0.4:
2.5.9:
       INET/inet_error: read errno = 10054, client address = 127.0.0.1/3268, user = JOHN.-1.-1

3.0.4:
       INET/inet_error: read errno = 10054, client host = csprog, address = 127.0.0.1/3298, user = john

2.5.9.does not contain "client host = <name>" and *does* contain some suffix after user name (which is in uppercase).
Can these messages be unified ?