Tidy and fix logging.
[dcpomatic.git] / src / lib / encode_server.cc
1 /*
2     Copyright (C) 2012-2018 Carl Hetherington <cth@carlh.net>
3
4     This file is part of DCP-o-matic.
5
6     DCP-o-matic is free software; you can redistribute it and/or modify
7     it under the terms of the GNU General Public License as published by
8     the Free Software Foundation; either version 2 of the License, or
9     (at your option) any later version.
10
11     DCP-o-matic is distributed in the hope that it will be useful,
12     but WITHOUT ANY WARRANTY; without even the implied warranty of
13     MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
14     GNU General Public License for more details.
15
16     You should have received a copy of the GNU General Public License
17     along with DCP-o-matic.  If not, see <http://www.gnu.org/licenses/>.
18
19 */
20
21 /** @file src/encode_server.cc
22  *  @brief Class to describe a server to which we can send
23  *  encoding work, and a class to implement such a server.
24  */
25
26 #include "encode_server.h"
27 #include "util.h"
28 #include "dcpomatic_socket.h"
29 #include "image.h"
30 #include "dcp_video.h"
31 #include "config.h"
32 #include "cross.h"
33 #include "player_video.h"
34 #include "compose.hpp"
35 #include "log.h"
36 #include "dcpomatic_log.h"
37 #include "encoded_log_entry.h"
38 #include "version.h"
39 #include <dcp/raw_convert.h>
40 #include <libcxml/cxml.h>
41 #include <libxml++/libxml++.h>
42 #include <boost/algorithm/string.hpp>
43 #include <boost/scoped_array.hpp>
44 #include <boost/foreach.hpp>
45 #ifdef HAVE_VALGRIND_H
46 #include <valgrind/memcheck.h>
47 #endif
48 #include <string>
49 #include <vector>
50 #include <iostream>
51
52 #include "i18n.h"
53
54 using std::string;
55 using std::vector;
56 using std::list;
57 using std::cout;
58 using std::cerr;
59 using std::fixed;
60 using boost::shared_ptr;
61 using boost::thread;
62 using boost::bind;
63 using boost::scoped_array;
64 using boost::optional;
65 using dcp::Size;
66 using dcp::Data;
67 using dcp::raw_convert;
68
69 EncodeServer::EncodeServer (bool verbose, int num_threads)
70 #if !defined(RUNNING_ON_VALGRIND) || RUNNING_ON_VALGRIND == 0
71         : Server (ENCODE_FRAME_PORT)
72 #else
73         : Server (ENCODE_FRAME_PORT, 2400)
74 #endif
75         , _verbose (verbose)
76         , _num_threads (num_threads)
77 {
78
79 }
80
81 EncodeServer::~EncodeServer ()
82 {
83         {
84                 boost::mutex::scoped_lock lm (_mutex);
85                 _terminate = true;
86                 _empty_condition.notify_all ();
87                 _full_condition.notify_all ();
88         }
89
90         BOOST_FOREACH (boost::thread* i, _worker_threads) {
91                 /* Ideally this would be a DCPOMATIC_ASSERT(i->joinable()) but we
92                    can't throw exceptions from a destructor.
93                 */
94                 if (i->joinable ()) {
95                         i->join ();
96                 }
97                 delete i;
98         }
99
100         if (_broadcast.socket) {
101                 _broadcast.socket->close ();
102         }
103         _broadcast.io_service.stop ();
104         if (_broadcast.thread) {
105                 /* Ideally this would be a DCPOMATIC_ASSERT(_broadcast.thread->joinable()) but we
106                    can't throw exceptions from a destructor.
107                 */
108                 if (_broadcast.thread->joinable ()) {
109                         _broadcast.thread->join ();
110                 }
111                 delete _broadcast.thread;
112         }
113 }
114
115 /** @param after_read Filled in with gettimeofday() after reading the input from the network.
116  *  @param after_encode Filled in with gettimeofday() after encoding the image.
117  */
118 int
119 EncodeServer::process (shared_ptr<Socket> socket, struct timeval& after_read, struct timeval& after_encode)
120 {
121         uint32_t length = socket->read_uint32 ();
122         scoped_array<char> buffer (new char[length]);
123         socket->read (reinterpret_cast<uint8_t*> (buffer.get()), length);
124
125         string s (buffer.get());
126         shared_ptr<cxml::Document> xml (new cxml::Document ("EncodingRequest"));
127         xml->read_string (s);
128         /* This is a double-check; the server shouldn't even be on the candidate list
129            if it is the wrong version, but it doesn't hurt to make sure here.
130         */
131         if (xml->number_child<int> ("Version") != SERVER_LINK_VERSION) {
132                 cerr << "Mismatched server/client versions\n";
133                 LOG_ERROR_NC ("Mismatched server/client versions");
134                 return -1;
135         }
136
137         shared_ptr<PlayerVideo> pvf (new PlayerVideo (xml, socket));
138
139         DCPVideo dcp_video_frame (pvf, xml);
140
141         gettimeofday (&after_read, 0);
142
143         Data encoded = dcp_video_frame.encode_locally ();
144
145         gettimeofday (&after_encode, 0);
146
147         try {
148                 socket->write (encoded.size());
149                 socket->write (encoded.data().get(), encoded.size());
150         } catch (std::exception& e) {
151                 cerr << "Send failed; frame " << dcp_video_frame.index() << "\n";
152                 LOG_ERROR ("Send failed; frame %1", dcp_video_frame.index());
153                 throw;
154         }
155
156         return dcp_video_frame.index ();
157 }
158
159 void
160 EncodeServer::worker_thread ()
161 {
162         while (true) {
163                 boost::mutex::scoped_lock lock (_mutex);
164                 while (_queue.empty () && !_terminate) {
165                         _empty_condition.wait (lock);
166                 }
167
168                 if (_terminate) {
169                         return;
170                 }
171
172                 shared_ptr<Socket> socket = _queue.front ();
173                 _queue.pop_front ();
174
175                 lock.unlock ();
176
177                 int frame = -1;
178                 string ip;
179
180                 struct timeval start;
181                 struct timeval after_read;
182                 struct timeval after_encode;
183                 struct timeval end;
184
185                 gettimeofday (&start, 0);
186
187                 try {
188                         frame = process (socket, after_read, after_encode);
189                         ip = socket->socket().remote_endpoint().address().to_string();
190                 } catch (std::exception& e) {
191                         cerr << "Error: " << e.what() << "\n";
192                         LOG_ERROR ("Error: %1", e.what());
193                 }
194
195                 gettimeofday (&end, 0);
196
197                 socket.reset ();
198
199                 lock.lock ();
200
201                 if (frame >= 0) {
202                         struct timeval end;
203                         gettimeofday (&end, 0);
204
205                         shared_ptr<EncodedLogEntry> e (
206                                 new EncodedLogEntry (
207                                         frame, ip,
208                                         seconds(after_read) - seconds(start),
209                                         seconds(after_encode) - seconds(after_read),
210                                         seconds(end) - seconds(after_encode)
211                                         )
212                                 );
213
214                         if (_verbose) {
215                                 cout << e->get() << "\n";
216                         }
217
218                         dcpomatic_log->log (e);
219                 }
220
221                 _full_condition.notify_all ();
222         }
223 }
224
225 void
226 EncodeServer::run ()
227 {
228         LOG_GENERAL ("Server %1 (%2) starting with %3 threads", dcpomatic_version, dcpomatic_git_commit, _num_threads);
229         if (_verbose) {
230                 cout << "DCP-o-matic server starting with " << _num_threads << " threads.\n";
231         }
232
233         for (int i = 0; i < _num_threads; ++i) {
234                 thread* t = new thread (bind (&EncodeServer::worker_thread, this));
235 #ifdef DCPOMATIC_LINUX
236                 pthread_setname_np (t->native_handle(), "encode-server-worker");
237 #endif
238                 _worker_threads.push_back (t);
239         }
240
241         _broadcast.thread = new thread (bind (&EncodeServer::broadcast_thread, this));
242 #ifdef DCPOMATIC_LINUX
243         pthread_setname_np (_broadcast.thread->native_handle(), "encode-server-broadcast");
244 #endif
245
246         Server::run ();
247 }
248
249 void
250 EncodeServer::broadcast_thread ()
251 try
252 {
253         boost::asio::ip::address address = boost::asio::ip::address_v4::any ();
254         boost::asio::ip::udp::endpoint listen_endpoint (address, HELLO_PORT);
255
256         _broadcast.socket = new boost::asio::ip::udp::socket (_broadcast.io_service);
257         _broadcast.socket->open (listen_endpoint.protocol ());
258         _broadcast.socket->bind (listen_endpoint);
259
260         _broadcast.socket->async_receive_from (
261                 boost::asio::buffer (_broadcast.buffer, sizeof (_broadcast.buffer)),
262                 _broadcast.send_endpoint,
263                 boost::bind (&EncodeServer::broadcast_received, this)
264                 );
265
266         _broadcast.io_service.run ();
267 }
268 catch (...)
269 {
270         store_current ();
271 }
272
273 void
274 EncodeServer::broadcast_received ()
275 {
276         _broadcast.buffer[sizeof(_broadcast.buffer) - 1] = '\0';
277
278         if (strcmp (_broadcast.buffer, DCPOMATIC_HELLO) == 0) {
279                 /* Reply to the client saying what we can do */
280                 xmlpp::Document doc;
281                 xmlpp::Element* root = doc.create_root_node ("ServerAvailable");
282                 root->add_child("Threads")->add_child_text (raw_convert<string> (_worker_threads.size ()));
283                 root->add_child("Version")->add_child_text (raw_convert<string> (SERVER_LINK_VERSION));
284                 string xml = doc.write_to_string ("UTF-8");
285
286                 if (_verbose) {
287                         cout << "Offering services to master " << _broadcast.send_endpoint.address().to_string () << "\n";
288                 }
289
290                 try {
291                         shared_ptr<Socket> socket (new Socket);
292                         socket->connect (boost::asio::ip::tcp::endpoint (_broadcast.send_endpoint.address(), MAIN_SERVER_PRESENCE_PORT));
293                         socket->write (xml.length() + 1);
294                         socket->write ((uint8_t *) xml.c_str(), xml.length() + 1);
295                 } catch (...) {
296
297                 }
298
299                 try {
300                         shared_ptr<Socket> socket (new Socket);
301                         socket->connect (boost::asio::ip::tcp::endpoint (_broadcast.send_endpoint.address(), BATCH_SERVER_PRESENCE_PORT));
302                         socket->write (xml.length() + 1);
303                         socket->write ((uint8_t *) xml.c_str(), xml.length() + 1);
304                 } catch (...) {
305
306                 }
307         }
308
309         _broadcast.socket->async_receive_from (
310                 boost::asio::buffer (_broadcast.buffer, sizeof (_broadcast.buffer)),
311                 _broadcast.send_endpoint, boost::bind (&EncodeServer::broadcast_received, this)
312                 );
313 }
314
315 void
316 EncodeServer::handle (shared_ptr<Socket> socket)
317 {
318         boost::mutex::scoped_lock lock (_mutex);
319
320         /* Wait until the queue has gone down a bit */
321         while (_queue.size() >= _worker_threads.size() * 2 && !_terminate) {
322                 _full_condition.wait (lock);
323         }
324
325         _queue.push_back (socket);
326         _empty_condition.notify_all ();
327 }