Bug 36948

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

CC'ing all the big brains as I am unsure if this is the correct way to solve this

Do you need the (empty) OPEN method in Trapper actually ? You dont have a CLOSE either?

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

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>

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

Looks like Debian 12 uses "libnet-server-perl 2.013-2" while Ubuntu 22.04 uses "libnet-server-perl 2.009-2".

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

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

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.

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.

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.

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.

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

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

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

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

Not sure about the need for category => 'STDERR' btw

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

(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);

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

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.

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>

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>

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>

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>

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>

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>

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>

(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

(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

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

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

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

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

Thanks for all the hard work!

Pushed to main for the next 24.11.00 release as RM Assistant

Backported to 24.05.x for upcoming 24.05.02

Pushed to 23.11.x for 23.11.07

not backporting to 23.05.x unless requested

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.