Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Append the IP address of the remote host to error messages in firebird.log for TCP connections [CORE2493] #2906

Closed
firebird-automations opened this issue Jun 3, 2009 · 37 comments

Comments

@firebird-automations
Copy link
Collaborator

Submitted by: John Kilin (johnkilin)

Votes: 15

Commits: b7d8f28 737b5f8 9e5c39a 2820ede FirebirdSQL/fbt-repository@608b7d3 FirebirdSQL/fbt-repository@ee456a8 FirebirdSQL/fbt-repository@c620f65 FirebirdSQL/fbt-repository@7bdd463

====== 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.

@firebird-automations
Copy link
Collaborator Author

Modified by: @dyemanov

priority: Major [ 3 ] => Minor [ 4 ]

summary: Please, add IP address of remote host to error messages in firebird.log for TCP connections. => Append the IP address of the remote host to error messages in firebird.log for TCP connections

Version: 2.5 Beta 1 [ 10251 ] =>

@firebird-automations
Copy link
Collaborator Author

Commented by: @ibaseru

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

@firebird-automations
Copy link
Collaborator Author

Modified by: @dyemanov

assignee: Dmitry Yemanov [ dimitr ]

@firebird-automations
Copy link
Collaborator Author

Modified by: @dyemanov

Fix Version: 3.0 Alpha 1 [ 10331 ]

@firebird-automations
Copy link
Collaborator Author

Commented by: @dyemanov

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?

@firebird-automations
Copy link
Collaborator Author

Commented by: @dyemanov

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\)

@firebird-automations
Copy link
Collaborator Author

Commented by: @pmakowski

I like the last one (A shorter alternative)

@firebird-automations
Copy link
Collaborator Author

Commented by: @sim1984

Whether it is impossible to add this improvement in 2.5.2?

@firebird-automations
Copy link
Collaborator Author

Commented by: @dyemanov

Not for 2.5.2 for sure.

@firebird-automations
Copy link
Collaborator Author

Modified by: @dyemanov

status: Open [ 1 ] => In Progress [ 3 ]

@firebird-automations
Copy link
Collaborator Author

Commented by: @sim1984

Add there a line of connection
localhost:mydatabase or at least alias DB

@firebird-automations
Copy link
Collaborator Author

Commented by: @dyemanov

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.

@firebird-automations
Copy link
Collaborator Author

Commented by: @sim1984

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.

@firebird-automations
Copy link
Collaborator Author

Modified by: @dyemanov

Fix Version: 3.0 Beta 1 [ 10332 ]

Fix Version: 3.0 Alpha 1 [ 10331 ] =>

@firebird-automations
Copy link
Collaborator Author

Commented by: Jesus Angel Garcia Zarco (cointec)

If it is feasible, backport to version 2.5.X the information that is posible to record.

@firebird-automations
Copy link
Collaborator Author

Modified by: @dyemanov

Fix Version: 3.0 Beta 2 [ 10586 ]

Fix Version: 3.0 Beta 1 [ 10332 ] =>

@firebird-automations
Copy link
Collaborator Author

Commented by: @dyemanov

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.

@firebird-automations
Copy link
Collaborator Author

Commented by: @sim1984

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).

@firebird-automations
Copy link
Collaborator Author

Commented by: @dyemanov

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.

@firebird-automations
Copy link
Collaborator Author

Modified by: @dyemanov

Fix Version: 3.0 RC 1 [ 10584 ]

Fix Version: 3.0 Beta 2 [ 10586 ] =>

@firebird-automations
Copy link
Collaborator Author

Modified by: @dyemanov

status: In Progress [ 3 ] => Open [ 1 ]

@firebird-automations
Copy link
Collaborator Author

Modified by: @dyemanov

Fix Version: 3.0.0 [ 10048 ]

Fix Version: 3.0 RC 1 [ 10584 ] =>

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

assignee: Dmitry Yemanov [ dimitr ] => Vlad Khorsun [ hvlad ]

@firebird-automations
Copy link
Collaborator Author

Commented by: @hvlad

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

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

status: Open [ 1 ] => Resolved [ 5 ]

resolution: Fixed [ 1 ]

@firebird-automations
Copy link
Collaborator Author

Commented by: @pavel-zotov

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 ?

@firebird-automations
Copy link
Collaborator Author

Commented by: @hvlad

> 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

@firebird-automations
Copy link
Collaborator Author

Commented by: @pavel-zotov

>> 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.

@firebird-automations
Copy link
Collaborator Author

Commented by: @hvlad

>>> 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*)

@firebird-automations
Copy link
Collaborator Author

Commented by: @pavel-zotov

> 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 ?)

@firebird-automations
Copy link
Collaborator Author

Commented by: @dyemanov

Better ignore everything between "inet_error:" and "errno" tokens.

@firebird-automations
Copy link
Collaborator Author

Commented by: @pavel-zotov

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 ?

@firebird-automations
Copy link
Collaborator Author

Modified by: @pavel-zotov

status: Resolved [ 5 ] => Resolved [ 5 ]

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.

@firebird-automations
Copy link
Collaborator Author

Commented by: @hvlad

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.

@firebird-automations
Copy link
Collaborator Author

Commented by: @hvlad

Backported into v2.5.9

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

Fix Version: 2.5.9 [ 10862 ]

@firebird-automations
Copy link
Collaborator Author

Commented by: @pavel-zotov

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 ?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants