It used to be that logging for the SIP2 server was configured in SIPconfig.xml: <server-params min_servers='1' min_spare_servers='0' log_file='Sys::Syslog' syslog_ident='koha_sip' syslog_facility='local6' /> The last 3 lines are the relevant ones. These lines are still present in the template file for Debian packages: https://git.koha-community.org/Koha-community/Koha/src/branch/master/debian/templates/SIPconfig.xml Then "Bug 15253: Add Koha::Logger based logging for SIP2" added logging based on log4perl for SIP2. But as far as I can see, the remnants of syslog config makes the SIP2 server not run properly. To reproduce: If you are on a dev setup (e.g. kohadevbox), copy the log4perl template to the standard location: $ sudo cp kohaclone/debian/templates/log4perl-site.conf.in /etc/koha/log4perl-site.conf.in Create a new site, called siptest: $ sudo koha-create --create-db siptest Verify that /etc/koha/sites/siptest/log4perl.conf has a section for SIP: log4perl.logger.sip = DEBUG, SIP log4perl.appender.SIP=Log::Log4perl::Appender::File log4perl.appender.SIP.filename=/var/log/koha/siptest/sip.log log4perl.appender.SIP.mode=append log4perl.appender.SIP.layout=PatternLayout log4perl.appender.SIP.layout.ConversionPattern=[%d] [%p] %m %l %n log4perl.appender.SIP.utf8=1 Enable and start the SIP2 server: $ sudo koha-sip --enable siptest Enabling SIP server for siptest - edit /etc/koha/sites/siptest/SIPconfig.xml to configure $ sudo koha-sip --start siptest Use ps to check if the SIP server is actually running: $ ps aux | grep SIPServer siptest+ 20084 0.0 0.0 18708 1732 ? S 15:40 0:00 daemon --name=siptest-koha-sip --errlog=/var/log/koha/siptest/sip-error.log --stdout=/var/log/koha/siptest/sip.log --output=/var/log/koha/siptest/sip-output.log --verbose=1 --respawn --delay=30 --pidfiles=/var/run/koha/siptest --user=siptest-koha.siptest-koha -- perl /home/vagrant/kohaclone/lib/C4/SIP/SIPServer.pm /etc/koha/sites/siptest/SIPconfig.xml vagrant 20294 0.0 0.0 12780 968 pts/0 R+ 15:44 0:00 grep SIPServer This output means the daemon is running, but not the SIP-server itself. Edit /etc/koha/sites/siptest/SIPconfig.xml and remove these three lines: log_file='Sys::Syslog' syslog_ident='koha_sip' syslog_facility='local6' Then restarte the SIP2 server: $ sudo koha-sip --restart siptest Then run ps again: $ ps aux | grep SIPServer siptest+ 20383 0.0 0.0 18708 196 ? S 15:44 0:00 daemon --name=siptest-koha-sip --errlog=/var/log/koha/siptest/sip-error.log --stdout=/var/log/koha/siptest/sip.log --output=/var/log/koha/siptest/sip-output.log --verbose=1 --respawn --delay=30 --pidfiles=/var/run/koha/siptest --user=siptest-koha.siptest-koha -- perl /usr/share/koha/lib/C4/SIP/SIPServer.pm /etc/koha/sites/siptest/SIPconfig.xml siptest+ 20385 42.0 8.2 382120 169104 ? S 15:44 0:01 perl /usr/share/koha/lib/C4/SIP/SIPServer.pm /etc/koha/sites/siptest/SIPconfig.xml siptest+ 20390 0.0 7.6 382120 156460 ? S 15:44 0:00 perl /usr/share/koha/lib/C4/SIP/SIPServer.pm /etc/koha/sites/siptest/SIPconfig.xml vagrant 20392 0.0 0.0 12780 968 pts/0 S+ 15:44 0:00 grep SIPServer Lines that contain "perl /usr/share/koha/lib/C4/SIP/SIPServer.pm /etc/koha/sites/siptest/SIPconfig.xml" indicate the actual SIP2 server is running. I think what needs to be done is: - Remove the 3 syslog-related lines from etc/SIPconfig.xml and debian/templates/SIPconfig.xml - Add a note to the release notes that the 3 lines need to be removed from SIPconfig.xml fles that are in active use PS! I have not looked deeply at *why* those three config lines makes the SIPserver fail to run, just that removing them fixes the problem.
Created attachment 119431 [details] [review] Bug 28122 - Remove old syslog config from SIPconfig.xml Bug 15253 added logging based on log4perl for SIP2, replacing the old logging to syslog. It seems that the remnants of the old syslog config makes the SIP2 server not run properly. To reproduce: - Create a site called e.g. siptest: $ sudo koha-create --create-db siptest - Verify that /etc/koha/sites/siptest/log4perl.conf has a section for SIP: log4perl.logger.sip = DEBUG, SIP log4perl.appender.SIP=Log::Log4perl::Appender::File log4perl.appender.SIP.filename=/var/log/koha/siptest/sip.log log4perl.appender.SIP.mode=append log4perl.appender.SIP.layout=PatternLayout log4perl.appender.SIP.layout.ConversionPattern=[%d] [%p] %m %l %n log4perl.appender.SIP.utf8=1 - Enable and start the SIP2 server: $ sudo koha-sip --enable siptest $ sudo koha-sip --start siptest - Use ps to check if the SIP server is actually running: $ ps aux | grep SIPServer If the output does not contain a line like this: "perl /usr/share/koha/lib/C4/SIP/SIPServer.pm /etc/koha/sites/siptest/SIPconfig.xml" it means the actual SIP2 server is not running To test: - Apply this patch - If you are on a dev setup (e.g. kohadevbox), copy the log4perl template to the standard location: $ sudo cp kohaclone/debian/templates/log4perl-site.conf.in \ /etc/koha/log4perl-site.conf.in - Create another site and check the output from ps again. If it contains one or more lines like "perl SIPServer.pm SIPconfig.xml" that means the server is actually running You can also check if the server is running properly by talking to it over telnet: $ telnet localhost <port number from SIPconfig.xml>
I spent a couple days figuring this out. Part of the problem was that the SIP2 server would never run, and there was no output to indicate why. The daemon would be running fine, but the SIP server would refuse to start. "sudo koha-sip --status <site>" would indicate everything was OK. Pretty much the only thing I could find in the logs was this, in /var/log/koha/koha/sip-error.log: 20210408 13:18:08 koha-koha-sip: client (pid 24379) exited with 1 status 20210408 13:18:09 koha-koha-sip: client (pid 24381) exited with 1 status 20210408 13:18:10 koha-koha-sip: client (pid 24385) exited with 1 status 20210408 13:18:10 koha-koha-sip: client (pid 24387) exited with 1 status 20210408 13:18:11 koha-koha-sip: client (pid 24389) exited with 1 status 20210408 13:18:11 koha-koha-sip: terminating too quickly, waiting 30 seconds 20210408 13:18:42 koha-koha-sip: client (pid 24394) exited with 1 status 20210408 13:18:43 koha-koha-sip: client (pid 24396) exited with 1 status 20210408 13:18:44 koha-koha-sip: client (pid 24398) exited with 1 status 20210408 13:18:45 koha-koha-sip: client (pid 24400) exited with 1 status 20210408 13:18:46 koha-koha-sip: client (pid 24402) exited with 1 status 20210408 13:18:46 koha-koha-sip: terminating too quickly, waiting 30 seconds Not overly helpful...
Hm, I wonder if there is another problem here. Given this config: <server-params min_servers='5' min_spare_servers='0' /> <listeners> <service port="8027/tcp" transport="RAW" protocol="SIP/2.00" timeout="360" /> <service port="127.0.0.1:6001/tcp" transport="RAW" protocol="SIP/2.00" client_timeout="360" timeout="360" /> I get this output when the SIP2 server starts up: 2021/04/14-10:09:03 C4::SIP::SIPServer (type Net::Server::PreFork) starting! pid(20848) Resolved [*]:8027 to [::]:8027, IPv6 Not including resolved host [0.0.0.0] IPv4 because it will be handled by [::] IPv6 Binding to TCP port 8027 on host :: with IPv6 Binding to TCP port 6001 on host 127.0.0.1 with IPv4 IPv6 is probably not what we want here? If I update the server-params section to this: <server-params min_servers='5' min_spare_servers='0' ipv='4' /> I get this: 2021/04/14-10:10:29 C4::SIP::SIPServer (type Net::Server::PreFork) starting! pid(22340) Binding to TCP port 6001 on host 127.0.0.1 with IPv4 Binding to TCP port 8027 on host * with IPv4 which is more in line with what I expect. The "ipv" setting is made avaiable by Net::Server: https://metacpan.org/pod/Net::Server#ipv-(IPv4-and-IPv6) "IPv6 is now available under Net::Server. It will be used automatically if an IPv6 address is passed, or if the ipv is set explicitly to IPv6, or if ipv is left as the default value of IPv*. This is a significant change from version 2.004 and earlier where the default value was IPv4." So maybe we need the release notes to say something like "Remove log_file, syslog_ident and syslog_facility from the server-params config, and add ipv to it"?
Made a backup of /etc/koha/log4perl-site.conf.in cp /etc/koha/log4perl-site.conf.in /etc/koha/log4perl-site.conf.in.bak > - Apply this patch > - If you are on a dev setup (e.g. kohadevbox), copy the log4perl template to the standard location: $ sudo cp kohaclone/debian/templates/log4perl-site.conf.in \ /etc/koha/log4perl-site.conf.in diff with the backup => they are the same :o
The lines in question are still there: 13 log_file='Sys::Syslog' 14 syslog_ident='koha_sip' 15 syslog_facility='local6'
(In reply to Katrin Fischer from comment #5) > The lines in question are still there: > > 13 log_file='Sys::Syslog' > 14 syslog_ident='koha_sip' > 15 syslog_facility='local6' I do believe this is still an issue. Koha SIP is breaking by default on newer version of Debian.
(In reply to Kyle M Hall from comment #6) > (In reply to Katrin Fischer from comment #5) > > The lines in question are still there: > > > > 13 log_file='Sys::Syslog' > > 14 syslog_ident='koha_sip' > > 15 syslog_facility='local6' > > I do believe this is still an issue. Koha SIP is breaking by default on > newer version of Debian. I think Magnus is still out for a while - would you be able to fix this one up?
Created attachment 170008 [details] [review] Bug 28122 - Remove old syslog config from SIPconfig.xml Bug 15253 added logging based on log4perl for SIP2, replacing the old logging to syslog. It seems that the remnants of the old syslog config makes the SIP2 server not run properly. To reproduce: - Create a site called e.g. siptest: $ sudo koha-create --create-db siptest - Verify that /etc/koha/sites/siptest/log4perl.conf has a section for SIP: log4perl.logger.sip = DEBUG, SIP log4perl.appender.SIP=Log::Log4perl::Appender::File log4perl.appender.SIP.filename=/var/log/koha/siptest/sip.log log4perl.appender.SIP.mode=append log4perl.appender.SIP.layout=PatternLayout log4perl.appender.SIP.layout.ConversionPattern=[%d] [%p] %m %l %n log4perl.appender.SIP.utf8=1 - Enable and start the SIP2 server: $ sudo koha-sip --enable siptest $ sudo koha-sip --start siptest - Use ps to check if the SIP server is actually running: $ ps aux | grep SIPServer If the output does not contain a line like this: "perl /usr/share/koha/lib/C4/SIP/SIPServer.pm /etc/koha/sites/siptest/SIPconfig.xml" it means the actual SIP2 server is not running To test: - Apply this patch - If you are on a dev setup (e.g. kohadevbox), copy the log4perl template to the standard location: $ sudo cp kohaclone/debian/templates/log4perl-site.conf.in \ /etc/koha/log4perl-site.conf.in - Create another site and check the output from ps again. If it contains one or more lines like "perl SIPServer.pm SIPconfig.xml" that means the server is actually running You can also check if the server is running properly by talking to it over telnet: $ telnet localhost <port number from SIPconfig.xml>
Created attachment 170009 [details] [review] Bug 28122 - Remove old syslog config from SIPconfig.xml Bug 15253 added logging based on log4perl for SIP2, replacing the old logging to syslog. It seems that the remnants of the old syslog config makes the SIP2 server not run properly. To reproduce: - Create a site called e.g. siptest: $ sudo koha-create --create-db siptest - Verify that /etc/koha/sites/siptest/log4perl.conf has a section for SIP: log4perl.logger.sip = DEBUG, SIP log4perl.appender.SIP=Log::Log4perl::Appender::File log4perl.appender.SIP.filename=/var/log/koha/siptest/sip.log log4perl.appender.SIP.mode=append log4perl.appender.SIP.layout=PatternLayout log4perl.appender.SIP.layout.ConversionPattern=[%d] [%p] %m %l %n log4perl.appender.SIP.utf8=1 - Enable and start the SIP2 server: $ sudo koha-sip --enable siptest $ sudo koha-sip --start siptest - Use ps to check if the SIP server is actually running: $ ps aux | grep SIPServer If the output does not contain a line like this: "perl /usr/share/koha/lib/C4/SIP/SIPServer.pm /etc/koha/sites/siptest/SIPconfig.xml" it means the actual SIP2 server is not running To test: - Apply this patch - If you are on a dev setup (e.g. kohadevbox), copy the log4perl template to the standard location: $ sudo cp kohaclone/debian/templates/log4perl-site.conf.in \ /etc/koha/log4perl-site.conf.in - Create another site and check the output from ps again. If it contains one or more lines like "perl SIPServer.pm SIPconfig.xml" that means the server is actually running You can also check if the server is running properly by talking to it over telnet: $ telnet localhost <port number from SIPconfig.xml>
Created attachment 170010 [details] [review] Bug 28122 - Remove old syslog config from SIPconfig.xml Bug 15253 added logging based on log4perl for SIP2, replacing the old logging to syslog. It seems that the remnants of the old syslog config makes the SIP2 server not run properly. To reproduce: - Create a site called e.g. siptest: $ sudo koha-create --create-db siptest - Verify that /etc/koha/sites/siptest/log4perl.conf has a section for SIP: log4perl.logger.sip = DEBUG, SIP log4perl.appender.SIP=Log::Log4perl::Appender::File log4perl.appender.SIP.filename=/var/log/koha/siptest/sip.log log4perl.appender.SIP.mode=append log4perl.appender.SIP.layout=PatternLayout log4perl.appender.SIP.layout.ConversionPattern=[%d] [%p] %m %l %n log4perl.appender.SIP.utf8=1 - Enable and start the SIP2 server: $ sudo koha-sip --enable siptest $ sudo koha-sip --start siptest - Use ps to check if the SIP server is actually running: $ ps aux | grep SIPServer If the output does not contain a line like this: "perl /usr/share/koha/lib/C4/SIP/SIPServer.pm /etc/koha/sites/siptest/SIPconfig.xml" it means the actual SIP2 server is not running To test: - Apply this patch - If you are on a dev setup (e.g. kohadevbox), copy the log4perl template to the standard location: $ sudo cp kohaclone/debian/templates/log4perl-site.conf.in \ /etc/koha/log4perl-site.conf.in - Create another site and check the output from ps again. If it contains one or more lines like "perl SIPServer.pm SIPconfig.xml" that means the server is actually running You can also check if the server is running properly by talking to it over telnet: $ telnet localhost <port number from SIPconfig.xml> Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Thanks for the rescue, Kyle :)
git bz apply 28122 [...] No changes -- Patch already applied. Bug 36948 already made those changes. But how did your signoff work Kyle? [U+1F92F]
(In reply to Victor Grousset/tuxayo from comment #12) > git bz apply 28122 > > [...] > No changes -- Patch already applied. > > Bug 36948 already made those changes. > > But how did your signoff work Kyle? [U+1F92F] I have no idea! I can only speculate that I didn't have the latest main checked out. It looks like the same fix is in stable and oldstable. For the life of me I can't imagine I would have had something else checked out. Was fixed with a follow-up in bug 36948