Bug 28122 - Remove old syslog config from SIPconfig.xml
Summary: Remove old syslog config from SIPconfig.xml
Status: Failed QA
Alias: None
Product: Koha
Classification: Unclassified
Component: SIP2 (show other bugs)
Version: Main
Hardware: All All
: P5 - low major (vote)
Assignee: Magnus Enger
QA Contact: Testopia
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2021-04-09 14:05 UTC by Magnus Enger
Modified: 2023-07-01 07:41 UTC (History)
5 users (show)

See Also:
Change sponsored?: ---
Patch complexity: Small patch
Documentation contact:
Documentation submission:
Text to go in the release notes:
Version(s) released in:


Attachments
Bug 28122 - Remove old syslog config from SIPconfig.xml (2.59 KB, patch)
2021-04-09 18:53 UTC, Magnus Enger
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Magnus Enger 2021-04-09 14:05:45 UTC
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.
Comment 1 Magnus Enger 2021-04-09 18:53:29 UTC
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>
Comment 2 Magnus Enger 2021-04-09 18:59:42 UTC
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...
Comment 3 Magnus Enger 2021-04-14 08:25:59 UTC
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"?
Comment 4 Victor Grousset/tuxayo 2021-04-24 19:29:33 UTC
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
Comment 5 Katrin Fischer 2023-07-01 07:41:42 UTC
The lines in question are still there:

 13     log_file='Sys::Syslog'
 14     syslog_ident='koha_sip'
 15     syslog_facility='local6'