Bug 36948 - Adjust SIPconfig for log_file and IP version
Summary: Adjust SIPconfig for log_file and IP version
Status: Pushed to oldstable
Alias: None
Product: Koha
Classification: Unclassified
Component: SIP2 (show other bugs)
Version: Main
Hardware: All All
: P5 - low normal
Assignee: Nick Clemens (kidclamp)
QA Contact: Testopia
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2024-05-23 13:56 UTC by Nick Clemens (kidclamp)
Modified: 2024-07-29 20:48 UTC (History)
11 users (show)

See Also:
Change sponsored?: ---
Patch complexity: ---
Documentation contact:
Documentation submission:
Text to go in the release notes:
This fixes issues with logging and default ports in the SIP configuration for Debian 12, when using the koha-testing-docker (KTD) development environment - these issues were causing the SIP service to stop working. Changes include updating the SIPconfig.xml template to: - fix the logging issue (Debian 12 uses journal instead of syslog, use chomp for SIP log4perl configuration, log all SIP issues to sip.log by default) - fix the port issue (allows using IPv4 and IPv6 for the port settings, configures the default template to use IPv4)
Version(s) released in:
24.11.00,24.05.02,23.11.07
Circulation function:


Attachments
Bug 36948: Resolve SIP issues in D12 (1.90 KB, patch)
2024-05-23 14:01 UTC, Nick Clemens (kidclamp)
Details | Diff | Splinter Review
Bug 36948: Resolve SIP issues in D12 (1.94 KB, patch)
2024-05-23 20:22 UTC, David Nind
Details | Diff | Splinter Review
Bug 36948: Resolve SIP issues in D12 (2.04 KB, patch)
2024-05-24 08:52 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 36948: (follow-up) Remove log_file param, adjust caller_depth (2.07 KB, patch)
2024-05-24 08:52 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 36948: (follow-up) Allow IPv[46] in port config (2.72 KB, patch)
2024-05-24 08:52 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 36948: (follow-up) Add chomp to sip log4perl config (1.11 KB, patch)
2024-05-24 08:52 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 36948: (follow-up) Remove log_file param, adjust caller_depth (1.99 KB, patch)
2024-05-24 08:53 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 36948: (follow-up) Allow IPv[46] in port config (2.72 KB, patch)
2024-05-24 08:53 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 36948: (follow-up) Add chomp to sip log4perl config (1.11 KB, patch)
2024-05-24 08:53 UTC, Marcel de Rooy
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Nick Clemens (kidclamp) 2024-05-23 13:56:45 UTC
On my Koha testing docker I was finding that SIP kept dying, though I could find no reason in the logs.

  22 20240523 11:24:28 kohadev-koha-sip: client (pid 1831) exited with 1 status, respawning
  23 20240523 11:24:29 kohadev-koha-sip: client (pid 1877) exited with 1 status, respawning
  24 20240523 11:24:31 kohadev-koha-sip: client (pid 1878) exited with 1 status, respawning
  25 20240523 11:24:33 kohadev-koha-sip: client (pid 1879) exited with 1 status, respawning
  26 20240523 11:24:34 kohadev-koha-sip: client (pid 1880) exited with 1 status, respawning
  27 20240523 11:24:34 kohadev-koha-sip: terminating too quickly, waiting 30 seconds
  28 20240523 11:25:04 kohadev-koha-sip: end of 30 second respawn attempt burst delay

I edited tie SIP config:
log_file='/var/log/koha/kohadev/sip.log'

Then I could see:
3724 [2024/05/23 13:17:30] [15317] [WARN] [undef]@[undef]: >&_SERVER_LOG C4::SIP::Trapper::OPEN /kohadevbox/koha/C4/SIP/Trapper.pm (43)
3725 2024/05/23-13:17:30 C4::SIP::SIPServer (type Net::Server::PreFork) starting! pid(15317)
3726 Resolved [*]:8023 to [::]:8023, IPv6 
3727 Not including resolved host [0.0.0.0] IPv4 because it will be handled by [::] IPv6
3728 Binding to TCP port 6001 on host 127.0.0.1 with IPv4
3729 Binding to TCP port 8023 on host :: with IPv6
3730 2024/05/23-13:17:30 Can't connect to TCP port 8023 on :: [Invalid argument]
3731   at line 66 in file /usr/share/perl5/Net/Server/Proto/TCP.pm 
3732 2024/05/23-13:17:30 Server closing!

I removed the 8023 section from SIPconfig and it worked! 

Then I talked to Kyle and we found it could be resolved with:
port="127.0.0.1:8023/tcp"

To resolve the OPEN error:
+sub OPEN {
+    return 1;
+}
+
Comment 1 Nick Clemens (kidclamp) 2024-05-23 14:01:32 UTC
Created attachment 167112 [details] [review]
Bug 36948: Resolve SIP issues in D12

My Koha testing docker SIP started dying repeatedly after launch. After investigation, I
found it was a problem with logging and default ports.

In D12 there is no syslog anymore, everythign uses journal. Four our purposes, lets log SIP issues
to sip.log by default

Attaching a patch to clear things up.

To test:
1 - Open KTD/D12
2 - tail -f /var/log/koha/kohadev/*.log
3 - On another terminal 'restart_all'
4 - Wait a bit, notice SIP dying
5 - Apply patch
6 - Update SIPconfig:
    server-params:
    log_file='/var/log/koha/kohadev/sip.log'
    service with port 8023:
    port="127.0.0.1:8023/tcp"
7 - Restart all
8 - Confirm SIP no longer dies
Comment 2 Nick Clemens (kidclamp) 2024-05-23 14:03:27 UTC
CC'ing all the big brains as I am unsure if this is the correct way to solve this
Comment 3 Marcel de Rooy 2024-05-23 14:15:14 UTC
Do you need the (empty) OPEN method in Trapper actually ? You dont have a CLOSE either?
Comment 4 Nick Clemens (kidclamp) 2024-05-23 14:37:52 UTC
(In reply to Marcel de Rooy from comment #3)
> Do you need the (empty) OPEN method in Trapper actually ? You dont have a
> CLOSE either?

Without it I get:
3724 [2024/05/23 13:17:30] [15317] [WARN] [undef]@[undef]: >&_SERVER_LOG C4::SIP::Trapper::OPEN /kohadevbox/koha/C4/SIP/Trapper.pm (43)

Server does run, but this removes that error.
Comment 5 David Nind 2024-05-23 20:22:14 UTC
Created attachment 167134 [details] [review]
Bug 36948: Resolve SIP issues in D12

My Koha testing docker SIP started dying repeatedly after launch. After investigation, I
found it was a problem with logging and default ports.

In D12 there is no syslog anymore, everythign uses journal. Four our purposes, lets log SIP issues
to sip.log by default

Attaching a patch to clear things up.

To test:
1 - Open KTD/D12
2 - tail -f /var/log/koha/kohadev/*.log
3 - On another terminal 'restart_all'
4 - Wait a bit, notice SIP dying
5 - Apply patch
6 - Update SIPconfig:
    server-params:
    log_file='/var/log/koha/kohadev/sip.log'
    service with port 8023:
    port="127.0.0.1:8023/tcp"
7 - Restart all
8 - Confirm SIP no longer dies

Signed-off-by: David Nind <david@davidnind.com>
Comment 6 David Cook 2024-05-24 01:01:42 UTC
My SIP is working OK on my Koha 23.11.x on Ubuntu 22.04 which is based off Debian 12.

But I do see my SIP failing as described on Koha main on Debian 12. I think I noticed that recently, but it was in the "too hard basket" while I had other things to do.

--

I see what Nick means about the log file and the Trapper... although I've added a different bit of code to Trapper for now...

And I see the error...

[2024/05/24 01:00:23] [1009] [WARN] [undef]@[undef]: C4::SIP::Trapper=ARRAY(0x55900576a4e8)>&_SERVER_LOG at /kohadevbox/koha/C4/SIP/Trapper.pm line 39.
 C4::SIP::Trapper::PRINT /kohadevbox/koha/C4/SIP/Trapper.pm (34)
2024/05/24-01:00:23 C4::SIP::SIPServer (type Net::Server::PreFork) starting! pid(1009)
Resolved [*]:8023 to [::]:8023, IPv6
Not including resolved host [0.0.0.0] IPv4 because it will be handled by [::] IPv6
Binding to TCP port 6001 on host 127.0.0.1 with IPv4
Binding to TCP port 8023 on host :: with IPv6
2024/05/24-01:00:23 Can't connect to TCP port 8023 on :: [Invalid argument]
  at line 66 in file /usr/share/perl5/Net/Server/Proto/TCP.pm
Comment 7 David Cook 2024-05-24 01:48:35 UTC
Looks like Debian 12 uses "libnet-server-perl 2.013-2" while Ubuntu 22.04 uses "libnet-server-perl 2.009-2".
Comment 8 David Cook 2024-05-24 01:51:25 UTC
(In reply to David Cook from comment #7)
> Looks like Debian 12 uses "libnet-server-perl 2.013-2" while Ubuntu 22.04
> uses "libnet-server-perl 2.009-2".

Note that Ubuntu 22.04 there is no problem binding to *:8023:

LISTEN                          0                               4096                                                                  *:8023                                                                 *:*
 users:(("perl",pid=915,fd=18),("perl",pid=823,fd=18))

Interestingly, "epmd" is separately bound to 0.0.0.0 and [::]:
LISTEN                          0                               4096                                                            0.0.0.0:4369                                                           0.0.0.0:*
 users:(("epmd",pid=151,fd=3))
LISTEN                          0                               4096                                                               [::]:4369                                                              [::]:*
 users:(("epmd",pid=151,fd=4))
Comment 9 David Cook 2024-05-24 02:27:40 UTC
According to https://docs.docker.com/config/daemon/ipv6/ Docker doesn't support IPv6 out of the box.

Of course, I don't know how I'm seeing "[::]:4369" in the output of "ss" for epmd in that case, but whatever.

I'm noticing the following:

$ sysctl -a | grep ipv6 | grep "disable"
net.ipv6.conf.all.disable_ipv6 = 1

$ nc -l ::1 8008 -v -n
nc: Cannot assign requested address

--

Compare that with a normal Ubuntu 22.04 VM

# sysctl -a | grep ipv6 | grep "disable"
net.ipv6.conf.all.disable_ipv6 = 0

# nc -l ::1 8008 -n -v
Listening on ::1 8008
Comment 10 David Cook 2024-05-24 02:31:50 UTC
Regarding the 4369 thing... 

Notice that I can't connect to it on IPv6:

nc :: 4369 -v
nc: connect to :: port 4369 (tcp) failed: Cannot assign requested address

nc ::1 4369 -v
nc: connect to ::1 port 4369 (tcp) failed: Cannot assign requested address

--

Whereas on a normal Ubuntu server it's no problem:

# nc :: 22 -v
Connection to :: 22 port [tcp/ssh] succeeded!

nc ::1 22 -v
Connection to ::1 22 port [tcp/ssh] succeeded!

--

So overall... I'm happy with Nick's change to 'port="127.0.0.1:8023/tcp"'. It's a reasonable default generally speaking, and people on systems with IPv6 can always choose to change it.
Comment 11 David Cook 2024-05-24 02:33:55 UTC
Note I am raising an issue with Net::Server, since it should consult net.ipv6.conf.all.disable_ipv6 at the very least I reckon. Or fail more gracefully in its bindings.
Comment 12 David Cook 2024-05-24 02:42:36 UTC
Note: There are lots of ways to specify only IPv4 or to turn off IPv6 with Net::Server it seems.

We could set $ENV{'NO_IPV6'} or $ENV{'IPV'}=4. 

Or we could pass "IPv4" along in the port specification. 

With that said, I think I still stand by Nick's change. I think it's the simplest change to make here. 

That said, we might consider adding one of the environmental variables, as this same issue could pop up again in different ways.
Comment 13 David Cook 2024-05-24 02:56:40 UTC
I'm not so sure about the logging change TBH, so I'm going to Failed QA this one.

I think the only bug is the port specification, so I think this bug report should only deal with that.
Comment 14 David Cook 2024-05-24 03:18:39 UTC
Btw, I'm trying to think of a different bug title, but I'm struggling, since this is a Docker-specific issue. 

An alternative to any patch here would be to add one of those environmental variables to koha-testing-docker...
Comment 15 Marcel de Rooy 2024-05-24 06:43:42 UTC
(In reply to Nick Clemens (kidclamp) from comment #4)
> (In reply to Marcel de Rooy from comment #3)
> > Do you need the (empty) OPEN method in Trapper actually ? You dont have a
> > CLOSE either?
> 
> Without it I get:
> 3724 [2024/05/23 13:17:30] [15317] [WARN] [undef]@[undef]: >&_SERVER_LOG
> C4::SIP::Trapper::OPEN /kohadevbox/koha/C4/SIP/Trapper.pm (43)
> 
> Server does run, but this removes that error.

Net::Server tries to redirect STDERR to STDOUT:

"If a log_file is given or if setsid is set, STDIN and STDOUT will automatically be opened to /dev/null and STDERR will be opened to STDOUT. This will prevent any output from ending up at the terminal."
Comment 16 Marcel de Rooy 2024-05-24 07:41:17 UTC
(In reply to David Cook from comment #13)
> I'm not so sure about the logging change TBH, so I'm going to Failed QA this
> one.

I have experimented a bit with removing the log_file parameter to Net::Server. Since we are already catching STDERR with Trapper. But note that our logging in SIP still is a bit cumbersome (historical ballast).

We use C4::SIP::Logger. Which has been set in SIPServer:
    set_logger( Koha::Logger->get( { interface => 'sip' } ) );
And again in process_request:
    $self->{logger} = set_logger( Koha::Logger->get( { interface => 'sip' } ) );
But we also do:
    tie *STDERR, "C4::SIP::Trapper";
To redirect warns to Trapper. Which also calls Koha::Logger.
And Koha::Logger is yet another wrapper for Log::Log4perl.

So removing the log_file should be fine. We are already catching it to that file. We do not need the OPEN method since removing the log_file makes Net::Server no longer touch STDERR. And in the PRINT method we need to adjust the caller_depth. I tested with caller_depth +3 / -3 to get the 'real' caller. And I chomped the message with %m{chomp} in log4perl.conf to remove unneeded newlines in the logfile.
Comment 17 Marcel de Rooy 2024-05-24 07:50:36 UTC
(In reply to David Cook from comment #12)
> Note: There are lots of ways to specify only IPv4 or to turn off IPv6 with
> Net::Server it seems.
> 
> We could set $ENV{'NO_IPV6'} or $ENV{'IPV'}=4. 
> 
> Or we could pass "IPv4" along in the port specification. 
> 
> With that said, I think I still stand by Nick's change. I think it's the
> simplest change to make here. 
> 
> That said, we might consider adding one of the environmental variables, as
> this same issue could pop up again in different ways.

This seems to work best (included v4 in the port spec):
    <service
      port="127.0.0.1:6001/tcp/IPv4"
      transport="RAW"
      protocol="SIP/2.00"
      client_timeout="600"
      timeout="60" />

Log says:
[2024/05/24 07:48:32] [282769] [WARN] 2024/05/24-07:48:32 C4::SIP::SIPServer (type Net::Server::PreFork) starting! pid(282769) Net::Server::run /usr/share/perl5/Net/Server.pm (52)
[2024/05/24 07:48:32] [282769] [WARN] 2024/05/24-07:48:32 C4::SIP::SIPServer (type Net::Server::PreFork) starting! pid(282769) Net::Server::log /usr/share/perl5/Net/Server.pm (911)
[2024/05/24 07:48:32] [282769] [WARN] Binding to TCP port 6001 on host 127.0.0.1 with IPv4 Net::Server::bind /usr/share/perl5/Net/Server.pm (316)
[2024/05/24 07:48:32] [282769] [WARN] Binding to TCP port 6001 on host 127.0.0.1 with IPv4 Net::Server::log /usr/share/perl5/Net/Server.pm (911)
[2024/05/24 07:48:32] [282769] [WARN] Setting gid to "1000 1000" Net::Server::post_bind /usr/share/perl5/Net/Server.pm (379)
[2024/05/24 07:48:32] [282769] [WARN] Setting gid to "1000 1000" Net::Server::log /usr/share/perl5/Net/Server.pm (911)

In some other variants I saw it trying IPv6 still..
Comment 18 Marcel de Rooy 2024-05-24 07:55:12 UTC
Not sure about the need for category => 'STDERR' btw
Comment 19 Marcel de Rooy 2024-05-24 07:58:19 UTC
(In reply to Marcel de Rooy from comment #17)
> This seems to work best (included v4 in the port spec):

Startup is fine, but additional requests are not ?
Comment 20 Marcel de Rooy 2024-05-24 08:02:43 UTC
(In reply to Marcel de Rooy from comment #19)
> (In reply to Marcel de Rooy from comment #17)
> > This seems to work best (included v4 in the port spec):
> 
> Startup is fine, but additional requests are not ?

$self->{service} = $config->find_service($sockaddr, $port, $proto);
Comment 21 Marcel de Rooy 2024-05-24 08:40:34 UTC
(In reply to Marcel de Rooy from comment #20)
> (In reply to Marcel de Rooy from comment #19)
> > (In reply to Marcel de Rooy from comment #17)
> > > This seems to work best (included v4 in the port spec):
> > 
> > Startup is fine, but additional requests are not ?
> 
> $self->{service} = $config->find_service($sockaddr, $port, $proto);

Can be fixed quickly.
Comment 22 Marcel de Rooy 2024-05-24 08:41:19 UTC
setsid
Specifies whether or not the server should fork after the bind method to release itself from the command line and then run the POSIX::setsid() command to truly daemonize. Defaults to undef. If a log_file is given or if setsid is set, STDIN and STDOUT will automatically be opened to /dev/null and STDERR will be opened to STDOUT. This will prevent any output from ending up at the terminal.

The etc/SIPconfig.xml file does contain a setsid. Can we remove it ?
Note that the debian one does not.
Comment 23 Marcel de Rooy 2024-05-24 08:52:08 UTC
Created attachment 167147 [details] [review]
Bug 36948: Resolve SIP issues in D12

My Koha testing docker SIP started dying repeatedly after launch. After investigation, I
found it was a problem with logging and default ports.

In D12 there is no syslog anymore, everythign uses journal. Four our purposes, lets log SIP issues
to sip.log by default

Attaching a patch to clear things up.

To test:
1 - Open KTD/D12
2 - tail -f /var/log/koha/kohadev/*.log
3 - On another terminal 'restart_all'
4 - Wait a bit, notice SIP dying
5 - Apply patch
6 - Update SIPconfig:
    server-params:
    log_file='/var/log/koha/kohadev/sip.log'
    service with port 8023:
    port="127.0.0.1:8023/tcp"
7 - Restart all
8 - Confirm SIP no longer dies

Signed-off-by: David Nind <david@davidnind.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 24 Marcel de Rooy 2024-05-24 08:52:10 UTC
Created attachment 167148 [details] [review]
Bug 36948: (follow-up) Remove log_file param, adjust caller_depth

We keep OPEN when people still use log_file or setsid.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 25 Marcel de Rooy 2024-05-24 08:52:13 UTC
Created attachment 167149 [details] [review]
Bug 36948: (follow-up) Allow IPv[46] in port config

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 26 Marcel de Rooy 2024-05-24 08:52:15 UTC
Created attachment 167150 [details] [review]
Bug 36948: (follow-up) Add chomp to sip log4perl config

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 27 Marcel de Rooy 2024-05-24 08:53:43 UTC
Created attachment 167151 [details] [review]
Bug 36948: (follow-up) Remove log_file param, adjust caller_depth

We keep OPEN when people still use log_file or setsid.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 28 Marcel de Rooy 2024-05-24 08:53:46 UTC
Created attachment 167152 [details] [review]
Bug 36948: (follow-up) Allow IPv[46] in port config

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 29 Marcel de Rooy 2024-05-24 08:53:48 UTC
Created attachment 167153 [details] [review]
Bug 36948: (follow-up) Add chomp to sip log4perl config

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 30 Marcel de Rooy 2024-05-24 08:56:57 UTC
(In reply to Marcel de Rooy from comment #22)
> The etc/SIPconfig.xml file does contain a setsid. Can we remove it ?
> Note that the debian one does not.

Resolved this by keeping the OPEN routine
Comment 31 Marcel de Rooy 2024-05-24 09:06:14 UTC
(In reply to David Cook from comment #14)
> Btw, I'm trying to think of a different bug title, but I'm struggling, since
> this is a Docker-specific issue. 
> 
> An alternative to any patch here would be to add one of those environmental
> variables to koha-testing-docker...

Proposing a new title here. Keeping both issues btw
Comment 32 Kyle M Hall 2024-05-28 15:06:42 UTC
(In reply to David Cook from comment #13)
> I'm not so sure about the logging change TBH, so I'm going to Failed QA this
> one.
> 
> I think the only bug is the port specification, so I think this bug report
> should only deal with that.

with syslog going away in debian is this still an issue?
Comment 33 David Cook 2024-05-29 02:34:44 UTC
(In reply to Kyle M Hall from comment #32)
> (In reply to David Cook from comment #13)
> > I'm not so sure about the logging change TBH, so I'm going to Failed QA this
> > one.
> > 
> > I think the only bug is the port specification, so I think this bug report
> > should only deal with that.
> 
> with syslog going away in debian is this still an issue?

I'm not sure I follow. I meant that the bug reported was the crashing due to being unable to create the TCP socket bindings, so this report should just focus on that.

Logging can be handled as a separate report.

I figure it would make backporting and overall management easier, but if people disagree I won't stand in the way.
Comment 34 Marcel de Rooy 2024-05-29 11:34:55 UTC
(In reply to David Cook from comment #33)
> (In reply to Kyle M Hall from comment #32)
> > (In reply to David Cook from comment #13)
> > > I'm not so sure about the logging change TBH, so I'm going to Failed QA this
> > > one.
> > > 
> > > I think the only bug is the port specification, so I think this bug report
> > > should only deal with that.
> > 
> > with syslog going away in debian is this still an issue?
> 
> I'm not sure I follow. I meant that the bug reported was the crashing due to
> being unable to create the TCP socket bindings, so this report should just
> focus on that.
> 
> Logging can be handled as a separate report.
> 
> I figure it would make backporting and overall management easier, but if
> people disagree I won't stand in the way.

Is that really needed? A few tiny patches to split again?
Comment 35 Kyle M Hall 2024-05-29 15:49:28 UTC
> > I figure it would make backporting and overall management easier, but if
> > people disagree I won't stand in the way.
> 
> Is that really needed? A few tiny patches to split again?

I would agree. If anyone feels strongly enough to FQA this please do so!
Comment 36 Martin Renvoize 2024-06-11 07:14:22 UTC
Thanks for all the hard work!

Pushed to main for the next 24.11.00 release as RM Assistant
Comment 37 Lucas Gass 2024-07-03 16:20:02 UTC
Backported to 24.05.x for upcoming 24.05.02
Comment 38 Fridolin Somers 2024-07-17 13:55:04 UTC
Pushed to 23.11.x for 23.11.07
Comment 39 wainuiwitikapark 2024-07-19 03:24:59 UTC
not backporting to 23.05.x unless requested
Comment 40 David Nind 2024-07-29 20:48:27 UTC
I had a go at a release note - please update if I have got anything/everything wrong.

My understanding from attempting to read the comments is that this only affects using KTD with Debian 12 (not production installation of Koha), but the changes accommodate the differences when using other operating system images such as Ubuntu 22.04.