Thread: Logging which interface was connected to in log_line_prefix

Logging which interface was connected to in log_line_prefix

From
Greg Sabino Mullane
Date:
Someone on -general was asking about this, as they are listening on multiple IPs and would like to know which exact one clients were hitting. I took a quick look and we already have that information, so I grabbed some stuff from inet_server_addr and added it as part of a "%L" (for 'local interface'). Quick patch / POC attached.

Cheers,
Greg

Attachment

Re: Logging which interface was connected to in log_line_prefix

From
Cary Huang
Date:
The following review has been posted through the commitfest application:
make installcheck-world:  tested, passed
Implements feature:       tested, passed
Spec compliant:           tested, passed
Documentation:            tested, passed

Hi 

I did a quick test on this patch and it seems to work as expected. Originally I thought the patch would add the name of
"localinterface" such as "eth0", "eth1", "lo"... etc as %L log prefix format. Instead, it formats the local interface
IPaddresses , but I think it is fine too. 
 

I have tested this new addition with various types of IPs including IPv4, IPv4 and IPv6 local loop back addresses,
globalIPv6 address, linked local IPv6 address with interface specifier, it seems to format these IPs correctly
 

There is a comment in the patch that states:

/* We do not need clean_ipv6_addr here: just report verbatim */

I am not quite sure what it means, but I am guessing it means that the patch does not need to format the IPv6 addresses
inany specific way. For example, removing leading zeros or compressing consecutive zeros to make a IPv6 address
shorter.It may not be necessary to indicate this in a comment because In my test, if any of my interface's IPv6 address
haveconsecutive zeroes like this: 2000:0000:0000:0000:0000:0000:200:cafe/64, my network driver (Ubuntu 18.04) will
formatit as 2000::200:cafe, and the patch of course will read it as 2000::200:cafe, which is ... correct and clean.
 

thank you
Cary Huang
www.highgo.ca

Re: Logging which interface was connected to in log_line_prefix

From
Greg Sabino Mullane
Date:
Thank you for taking the time to review this. I've attached a new rebased version, which has no significant changes.
 
There is a comment in the patch that states:

/* We do not need clean_ipv6_addr here: just report verbatim */

I am not quite sure what it means, but I am guessing it means that the patch does not need to format the IPv6 addresses in any specific way.

Yes, basically correct. There is a kluge (their word, not mine) in utils/adt/network.c to strip the zone - see the comment for the  clean_ipv6_addr() function in that file. I added the patch comment in case some future person wonders why we don't "clean up" the ipv6 address, like other places in the code base do. We don't need to pass it back to anything else, so we can simply output the correct version, zone and all.

Cheers,
Greg

Attachment

Re: Logging which interface was connected to in log_line_prefix

From
Peter Eisentraut
Date:
On 06.03.24 16:59, Greg Sabino Mullane wrote:
> Someone on -general was asking about this, as they are listening on 
> multiple IPs and would like to know which exact one clients were 
> hitting. I took a quick look and we already have that information, so I 
> grabbed some stuff from inet_server_addr and added it as part of a "%L" 
> (for 'local interface'). Quick patch / POC attached.

I was confused by this patch title.  This feature does not log the 
interface (like "eth0" or "lo"), but the local address.  Please adjust 
the terminology.

I noticed that for Unix-domain socket connections, %r and %h write 
"[local]".  I think that should be done for this new placeholder as well.




Re: Logging which interface was connected to in log_line_prefix

From
Peter Eisentraut
Date:
On 01.05.24 19:04, Greg Sabino Mullane wrote:
> Thank you for taking the time to review this. I've attached a new 
> rebased version, which has no significant changes.
> 
>     There is a comment in the patch that states:
> 
>     /* We do not need clean_ipv6_addr here: just report verbatim */
> 
>     I am not quite sure what it means, but I am guessing it means that
>     the patch does not need to format the IPv6 addresses in any specific
>     way.
> 
> 
> Yes, basically correct. There is a kluge (their word, not mine) in 
> utils/adt/network.c to strip the zone - see the comment for the  
> clean_ipv6_addr() function in that file. I added the patch comment in 
> case some future person wonders why we don't "clean up" the ipv6 
> address, like other places in the code base do. We don't need to pass it 
> back to anything else, so we can simply output the correct version, zone 
> and all.

clean_ipv6_addr() needs to be called before trying to convert a string 
representation into inet/cidr types.  This is not what is happening 
here.  So the comment is not applicable.




Re: Logging which local address was connected to in log_line_prefix

From
Greg Sabino Mullane
Date:
Peter, thank you for the feedback. Attached is a new patch with "address" rather than "interface", plus a new default of "local" if there is no address. I also removed the questionable comment, and updated the commitfest title.

Cheers,
Greg

Attachment

Re: Logging which local address was connected to in log_line_prefix

From
David Steele
Date:
On 5/24/24 22:33, Greg Sabino Mullane wrote:
> Peter, thank you for the feedback. Attached is a new patch with 
> "address" rather than "interface", plus a new default of "local" if 
> there is no address. I also removed the questionable comment, and 
> updated the commitfest title.

I tried the updated patch and it behaved as expected with [local] being 
logged for peer connections and an IP being logged for host connections.

One thing -- the changes in postgresql.conf.sample should use tabs to 
match the other lines. The patch uses spaces.

I also find the formatting in log_status_format() pretty awkward but I 
guess that will be handled by pgindent.

Regards,
-David



Re: Logging which local address was connected to in log_line_prefix

From
Greg Sabino Mullane
Date:
Thanks for the review. Please find attached a new version with proper tabs and indenting.

Cheers,
Greg

Attachment

Re: Logging which local address was connected to in log_line_prefix

From
David Steele
Date:
On 7/11/24 23:09, Greg Sabino Mullane wrote:
> Thanks for the review. Please find attached a new version with proper 
> tabs and indenting.

This looks good to me now. +1 overall for the feature.

Regards,
-David



Re: Logging which local address was connected to in log_line_prefix

From
Jim Jones
Date:
Hi Greg

On 11.07.24 18:09, Greg Sabino Mullane wrote:
> Thanks for the review. Please find attached a new version with proper
> tabs and indenting.
>
> Cheers,
> Greg
>

I'm testing this new log prefix and I'm wondering whether the following
behaviour is expected. The value of '%L' is different in the following
cases:


postgres=# SHOW log_line_prefix;
 log_line_prefix
-----------------
 %m [%p] -> %L
(1 row)

--

postgres=# SELECT 1/0;

2024-11-18 16:00:42.720 CET [3135117] -> 192.168.178.27 ERROR:  division
by zero
2024-11-18 16:00:42.720 CET [3135117] -> 192.168.178.27 STATEMENT: 
SELECT 1/0;

--

postgres=# SELECT pg_reload_conf();

2024-11-18 16:01:23.273 CET [3114980] -> [local] LOG:  received SIGHUP,
reloading configuration files

--

postgres=# CHECKPOINT;

2024-11-18 16:01:46.758 CET [3114981] -> [local] LOG:  checkpoint
starting: immediate force wait
2024-11-18 16:01:46.769 CET [3114981] -> [local] LOG:  checkpoint
complete: wrote 0 buffers (0.0%), wrote 0 SLRU buffers; 0 WAL file(s)
added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.012
s; sync files=0, longest=0.000 s, average=0.000 s; distance=0 kB,
estimate=25924 kB; lsn=0/26166430, redo lsn=0/261663D8


Is it supposed to be like this?


Thanks for the patch!

-- 
Jim




Re: Logging which local address was connected to in log_line_prefix

From
Greg Sabino Mullane
Date:
On Mon, Nov 18, 2024 at 10:07 AM Jim Jones <jim.jones@uni-muenster.de> wrote:
2024-11-18 16:00:42.720 CET [3135117] -> 192.168.178.27 STATEMENT: 
...
2024-11-18 16:01:23.273 CET [3114980] -> [local] LOG:  received SIGHUP,
...
2024-11-18 16:01:46.769 CET [3114981] -> [local] LOG:  checkpoint
Is it supposed to be like this?

Great question. I think "supposed to" is a bit of a stretch, but I presume it's the difference between a client connecting and using its connection information versus an already existing backend process, which is always going to be "local".

Overall this makes sense, as that checkpoint example above is coming from the checkpointer background process at 3114981, not the backend process that happened to trigger it. And 3114981 has no way of knowing the details of the caller's connection.

FWIW, the patch still applies cleanly to head as of 2/27/2025, so no rebase needed.

Cheers,
Greg

--
Enterprise Postgres Software Products & Tech Support