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