Bug 15253: Log trapped errors as log level 'warn' instead of 'error'
[koha.git] / C4 / SIP / SIPServer.pm
1 #!/usr/bin/perl
2 package C4::SIP::SIPServer;
3
4 use strict;
5 use warnings;
6 use FindBin qw($Bin);
7 use lib "$Bin";
8 use Net::Server::PreFork;
9 use IO::Socket::INET;
10 use Socket qw(:DEFAULT :crlf);
11 use Scalar::Util qw(blessed);
12 require UNIVERSAL::require;
13
14 use C4::Context;
15 use C4::SIP::Sip qw(siplog);
16 use C4::SIP::Sip::Constants qw(:all);
17 use C4::SIP::Sip::Configuration;
18 use C4::SIP::Sip::Checksum qw(checksum verify_cksum);
19 use C4::SIP::Sip::MsgType qw( handle login_core );
20 use C4::SIP::Logger qw(set_logger);
21
22 use Koha::Caches;
23
24 use Koha::Logger;
25 use C4::SIP::Trapper;
26 tie *STDERR, "C4::SIP::Trapper";
27
28 use base qw(Net::Server::PreFork);
29
30 use constant LOG_SIP => "local6"; # Local alias for the logging facility
31
32 #
33 # Main  # not really, since package SIPServer
34 #
35 # FIXME: Is this a module or a script?  
36 # A script with no MAIN namespace?
37 # A module that takes command line args?
38
39 # Set interface to 'sip'
40 C4::Context->interface('sip');
41
42 my %transports = (
43     RAW    => \&raw_transport,
44     telnet => \&telnet_transport,
45 );
46
47 #
48 # Read configuration
49 #
50 my $config = C4::SIP::Sip::Configuration->new( $ARGV[0] );
51 my @parms;
52
53 #
54 # Ports to bind
55 #
56 foreach my $svc (keys %{$config->{listeners}}) {
57     push @parms, "port=" . $svc;
58 }
59
60 #
61 # Logging
62 #
63 # Log lines look like this:
64 # Jun 16 21:21:31 server08 steve_sip[19305]: ILS::Transaction::Checkout performing checkout...
65 # [  TIMESTAMP  ] [ HOST ] [ IDENT ]  PID  : Message...
66 #
67 # The IDENT is determined by config file 'server-params' arguments
68
69
70 #
71 # Server Management: set parameters for the Net::Server::PreFork
72 # module.  The module silently ignores parameters that it doesn't
73 # recognize, and complains about invalid values for parameters
74 # that it does.
75 #
76 if (defined($config->{'server-params'})) {
77     while (my ($key, $val) = each %{$config->{'server-params'}}) {
78                 push @parms, $key . '=' . $val;
79     }
80 }
81
82
83 #
84 # This is the main event.
85 __PACKAGE__ ->run(@parms);
86
87 #
88 # Child
89 #
90
91 # process_request is the callback used by Net::Server to handle
92 # an incoming connection request.
93
94 sub process_request {
95     my $self = shift;
96     my $service;
97     my ($sockaddr, $port, $proto);
98     my $transport;
99
100     $self->{config} = $config;
101
102     # Flushing L1 to make sure the request will be processed using the correct data
103     Koha::Caches->flush_L1_caches();
104
105     $self->{account} = undef;  # Clear out the account from the last request, it may be different
106     $self->{logger} = set_logger( Koha::Logger->get( { interface => 'sip' } ) );
107
108     # Flush previous MDCs to prevent accidentally leaking incorrect MDC-entries
109     Log::Log4perl::MDC->put( "accountid", undef );
110     Log::Log4perl::MDC->put( "peeraddr",  undef );
111
112     my $sockname = getsockname(STDIN);
113
114     # Check if socket connection is IPv6 before resolving address
115     my $family = Socket::sockaddr_family($sockname);
116     if ($family == AF_INET6) {
117       ($port, $sockaddr) = sockaddr_in6($sockname);
118       $sockaddr = Socket::inet_ntop(AF_INET6, $sockaddr);
119     } else {
120       ($port, $sockaddr) = sockaddr_in($sockname);
121       $sockaddr = inet_ntoa($sockaddr);
122     }
123     $proto = $self->{server}->{client}->NS_proto();
124
125     $self->{service} = $config->find_service($sockaddr, $port, $proto);
126
127     if (!defined($self->{service})) {
128                 siplog("LOG_ERR", "process_request: Unknown recognized server connection: %s:%s/%s", $sockaddr, $port, $proto);
129                 die "process_request: Bad server connection";
130     }
131
132     $transport = $transports{$self->{service}->{transport}};
133
134     if (!defined($transport)) {
135                 siplog("LOG_WARNING", "Unknown transport '%s', dropping", $service->{transport});
136                 return;
137     } else {
138                 &$transport($self);
139     }
140     return;
141 }
142
143 #
144 # Transports
145 #
146
147 sub raw_transport {
148     my $self = shift;
149     my $input;
150     my $service = $self->{service};
151     # If using Net::Server::PreFork you may already have account set from a previous session
152     # Ensure you dont
153     if ($self->{account}) {
154         delete $self->{account};
155     }
156
157     # Timeout the while loop if we get stuck in it
158     # In practice it should only iterate once but be prepared
159     local $SIG{ALRM} = sub { die 'raw transport Timed Out!' };
160     my $timeout = $self->get_timeout({ transport => 1 });
161     siplog('LOG_DEBUG', "raw_transport: timeout is $timeout");
162     alarm $timeout;
163     while (!$self->{account}) {
164         $input = read_request();
165         if (!$input) {
166             # EOF on the socket
167             siplog("LOG_INFO", "raw_transport: shutting down: EOF during login");
168             return;
169         }
170         $input =~ s/[\r\n]+$//sm; # Strip off trailing line terminator(s)
171         my $reg = qr/^${\(LOGIN)}/;
172         last if $input !~ $reg ||
173             C4::SIP::Sip::MsgType::handle($input, $self, LOGIN);
174     }
175     alarm 0;
176
177     $self->{logger} = set_logger(
178         Koha::Logger->get(
179             {
180                 interface => 'sip',
181                 category  => $self->{account}->{id}, # Add id to namespace
182             }
183         )
184     );
185
186     # Set MDCs after properly authenticating
187     Log::Log4perl::MDC->put( "accountid", $self->{account}->{id} );
188     Log::Log4perl::MDC->put( "peeraddr",  $self->{server}->{peeraddr} );
189
190     siplog("LOG_DEBUG", "raw_transport: uname/inst: '%s/%s'",
191         $self->{account}->{id},
192         $self->{account}->{institution});
193     if (! $self->{account}->{id}) {
194         siplog("LOG_ERR","Login failed shutting down");
195         return;
196     }
197
198     $self->sip_protocol_loop();
199     siplog("LOG_INFO", "raw_transport: shutting down");
200     return;
201 }
202
203 sub get_clean_string {
204         my $string = shift;
205         if (defined $string) {
206                 siplog("LOG_DEBUG", "get_clean_string  pre-clean(length %s): %s", length($string), $string);
207                 chomp($string);
208                 $string =~ s/^[^A-z0-9]+//;
209                 $string =~ s/[^A-z0-9]+$//;
210                 siplog("LOG_DEBUG", "get_clean_string post-clean(length %s): %s", length($string), $string);
211         } else {
212                 siplog("LOG_INFO", "get_clean_string called on undefined");
213         }
214         return $string;
215 }
216
217 sub get_clean_input {
218         local $/ = "\012";
219         my $in = <STDIN>;
220         $in = get_clean_string($in);
221         while (my $extra = <STDIN>){
222                 siplog("LOG_ERR", "get_clean_input got extra lines: %s", $extra);
223         }
224         return $in;
225 }
226
227 sub telnet_transport {
228     my $self = shift;
229     my ($uid, $pwd);
230     my $strikes = 3;
231     my $account = undef;
232     my $input;
233     my $config  = $self->{config};
234     my $timeout = $self->get_timeout({ transport => 1 });
235     siplog("LOG_DEBUG", "telnet_transport: timeout is $timeout");
236
237     eval {
238         local $SIG{ALRM} = sub { die "telnet_transport: Timed Out ($timeout seconds)!\n"; };
239         local $| = 1;                   # Unbuffered output
240         $/ = "\015";            # Internet Record Separator (lax version)
241     # Until the terminal has logged in, we don't trust it
242     # so use a timeout to protect ourselves from hanging.
243
244         while ($strikes--) {
245             print "login: ";
246                 alarm $timeout;
247                 # $uid = &get_clean_input;
248                 $uid = <STDIN>;
249             print "password: ";
250             # $pwd = &get_clean_input || '';
251                 $pwd = <STDIN>;
252                 alarm 0;
253
254                 siplog("LOG_DEBUG", "telnet_transport 1: uid length %s, pwd length %s", length($uid), length($pwd));
255                 $uid = get_clean_string ($uid);
256                 $pwd = get_clean_string ($pwd);
257                 siplog("LOG_DEBUG", "telnet_transport 2: uid length %s, pwd length %s", length($uid), length($pwd));
258
259             if (exists ($config->{accounts}->{$uid})
260                 && ($pwd eq $config->{accounts}->{$uid}->{password})) {
261                         $account = $config->{accounts}->{$uid};
262                         if ( C4::SIP::Sip::MsgType::login_core($self,$uid,$pwd) ) {
263                 last;
264             }
265             }
266                 siplog("LOG_WARNING", "Invalid login attempt: '%s'", ($uid||''));
267                 print("Invalid login$CRLF");
268         }
269     }; # End of eval
270
271     if ($@) {
272                 siplog("LOG_ERR", "telnet_transport: Login timed out");
273                 die "Telnet Login Timed out";
274     } elsif (!defined($account)) {
275                 siplog("LOG_ERR", "telnet_transport: Login Failed");
276                 die "Login Failure";
277     } else {
278                 print "Login OK.  Initiating SIP$CRLF";
279     }
280
281     $self->{account} = $account;
282     siplog("LOG_DEBUG", "telnet_transport: uname/inst: '%s/%s'", $account->{id}, $account->{institution});
283     $self->sip_protocol_loop();
284     siplog("LOG_INFO", "telnet_transport: shutting down");
285     return;
286 }
287
288 #
289 # The terminal has logged in, using either the SIP login process
290 # over a raw socket, or via the pseudo-unix login provided by the
291 # telnet transport.  From that point on, both the raw and the telnet
292 # processes are the same:
293 sub sip_protocol_loop {
294     my $self = shift;
295     my $service = $self->{service};
296     my $config  = $self->{config};
297     my $timeout = $self->get_timeout({ client => 1 });
298
299     # The spec says the first message will be:
300     #     SIP v1: SC_STATUS
301     #     SIP v2: LOGIN (or SC_STATUS via telnet?)
302     # But it might be SC_REQUEST_RESEND.  As long as we get
303     # SC_REQUEST_RESEND, we keep waiting.
304
305     # Comprise reports that no other ILS actually enforces this
306     # constraint, so we'll relax about it too.
307     # Using the SIP "raw" login process, rather than telnet,
308     # requires the LOGIN message and forces SIP 2.00.  In that
309     # case, the LOGIN message has already been processed (above).
310
311     # In short, we'll take any valid message here.
312     eval {
313         local $SIG{ALRM} = sub {
314             siplog( 'LOG_DEBUG', 'Inactive: timed out' );
315             die "Timed Out!\n";
316         };
317         my $previous_alarm = alarm($timeout);
318
319         while ( my $inputbuf = read_request() ) {
320             if ( !defined $inputbuf ) {
321                 return;    #EOF
322             }
323             alarm($timeout);
324
325             unless ($inputbuf) {
326                 siplog( "LOG_ERR", "sip_protocol_loop: empty input skipped" );
327                 print("96$CR");
328                 next;
329             }
330
331             my $status = C4::SIP::Sip::MsgType::handle( $inputbuf, $self, q{} );
332             if ( !$status ) {
333                 siplog(
334                     "LOG_ERR",
335                     "sip_protocol_loop: failed to handle %s",
336                     substr( $inputbuf, 0, 2 )
337                 );
338             }
339             next if $status eq REQUEST_ACS_RESEND;
340         }
341         alarm($previous_alarm);
342         return;
343     };
344     if ( $@ =~ m/timed out/i ) {
345         return;
346     }
347     return;
348 }
349
350 sub read_request {
351       my $raw_length;
352       local $/ = "\015";
353
354     # proper SPEC: (octal) \015 = (hex) x0D = (dec) 13 = (ascii) carriage return
355       my $buffer = <STDIN>;
356       if ( defined $buffer ) {
357           STDIN->flush();    # clear an extra linefeed
358           chomp $buffer;
359           $raw_length = length $buffer;
360           $buffer =~ s/^\s*[^A-z0-9]+//s;
361 # Every line must start with a "real" character.  Not whitespace, control chars, etc.
362           $buffer =~ s/[^A-z0-9]+$//s;
363
364 # Same for the end.  Note this catches the problem some clients have sending empty fields at the end, like |||
365           $buffer =~ s/\015?\012//g;    # Extra line breaks must die
366           $buffer =~ s/\015?\012//s;    # Extra line breaks must die
367           $buffer =~ s/\015*\012*$//s;
368
369     # treat as one line to include the extra linebreaks we are trying to remove!
370       }
371       else {
372           siplog( 'LOG_DEBUG', 'EOF returned on read' );
373           return;
374       }
375       my $len = length $buffer;
376       if ( $len != $raw_length ) {
377           my $trim = $raw_length - $len;
378           siplog( 'LOG_DEBUG', "read_request trimmed $trim character(s) " );
379       }
380
381       siplog( 'LOG_INFO', "INPUT MSG: '$buffer'" );
382       return $buffer;
383 }
384
385 # $server->get_timeout({ $type => 1, fallback => $fallback });
386 #     where $type is transport | client | policy
387 #
388 # Centralizes all timeout logic.
389 # Transport refers to login process, client to active connections.
390 # Policy timeout is transaction timeout (used in ACS status message).
391 #
392 # Fallback is optional. If you do not pass transport, client or policy,
393 # you will get fallback or hardcoded default.
394
395 sub get_timeout {
396     my ( $server, $params ) = @_;
397     my $fallback = $params->{fallback} || 30;
398     my $service = $server->{service} // {};
399     my $config = $server->{config} // {};
400
401     if( $params->{transport} ||
402         ( $params->{client} && !exists $service->{client_timeout} )) {
403         # We do not allow zero values here.
404         # Note: config/timeout seems to be deprecated.
405         return $service->{timeout} || $config->{timeout} || $fallback;
406
407     } elsif( $params->{client} ) {
408         # We know that client_timeout exists now.
409         # We do allow zero values here to indicate no timeout.
410         return 0 if $service->{client_timeout} =~ /^0+$|\D/;
411         return $service->{client_timeout};
412
413     } elsif( $params->{policy} ) {
414         my $policy = $server->{policy} // {};
415         my $rv = sprintf( "%03d", $policy->{timeout} // 0 );
416         if( length($rv) != 3 ) {
417             siplog( "LOG_ERR", "Policy timeout has wrong size: '%s'", $rv );
418             return '000';
419         }
420         return $rv;
421
422     } else {
423         return $fallback;
424     }
425 }
426
427 1;
428
429 __END__