From aeb835a18c8df347e0ed68fb24631b320abeb611 Mon Sep 17 00:00:00 2001 From: Carl Hetherington Date: Fri, 9 Oct 2015 13:44:10 +0100 Subject: [PATCH] Logging improvements to allow prettier displays in the server GUI. --- src/lib/audio_decoder_stream.cc | 4 +- src/lib/config.cc | 4 +- src/lib/cross.cc | 6 +- src/lib/dcp_video.cc | 6 +- src/lib/encoded_log_entry.cc | 49 ++++++++++++++++ src/lib/encoded_log_entry.h | 35 +++++++++++ src/lib/encoder.cc | 8 +-- src/lib/environment_info.cc | 4 +- src/lib/ffmpeg.cc | 2 +- src/lib/ffmpeg_content.cc | 2 +- src/lib/ffmpeg_decoder.cc | 8 +-- src/lib/file_log.cc | 7 ++- src/lib/file_log.h | 2 +- src/lib/film.cc | 4 +- src/lib/job.cc | 4 +- src/lib/log.cc | 54 +++++------------ src/lib/log.h | 12 +--- src/lib/log_entry.cc | 70 ++++++++++++++++++++++ src/lib/log_entry.h | 51 ++++++++++++++++ src/lib/null_log.h | 2 +- src/lib/player.cc | 2 +- src/lib/server.cc | 28 ++++----- src/lib/string_log_entry.cc | 32 ++++++++++ src/lib/string_log_entry.h | 34 +++++++++++ src/lib/transcode_job.cc | 4 +- src/lib/upload_job.cc | 2 +- src/lib/video_content.cc | 2 +- src/lib/video_decoder.cc | 4 +- src/lib/writer.cc | 14 ++--- src/lib/wscript | 3 + src/tools/dcpomatic_server.cc | 100 +++++++++++++++++++++++++++----- src/wx/config_dialog.cc | 24 ++++---- 32 files changed, 449 insertions(+), 134 deletions(-) create mode 100644 src/lib/encoded_log_entry.cc create mode 100644 src/lib/encoded_log_entry.h create mode 100644 src/lib/log_entry.cc create mode 100644 src/lib/log_entry.h create mode 100644 src/lib/string_log_entry.cc create mode 100644 src/lib/string_log_entry.h diff --git a/src/lib/audio_decoder_stream.cc b/src/lib/audio_decoder_stream.cc index 97db8a93f..274bf2d54 100644 --- a/src/lib/audio_decoder_stream.cc +++ b/src/lib/audio_decoder_stream.cc @@ -62,7 +62,7 @@ AudioDecoderStream::get (Frame frame, Frame length, bool accurate) { shared_ptr dec; - _content->film()->log()->log (String::compose ("-> ADS has request for %1 %2", frame, length), Log::TYPE_DEBUG_DECODE); + _content->film()->log()->log (String::compose ("-> ADS has request for %1 %2", frame, length), LogEntry::TYPE_DEBUG_DECODE); Frame const end = frame + length - 1; @@ -136,7 +136,7 @@ AudioDecoderStream::get (Frame frame, Frame length, bool accurate) void AudioDecoderStream::audio (shared_ptr data, ContentTime time) { - _content->film()->log()->log (String::compose ("ADS receives %1 %2", time, data->frames ()), Log::TYPE_DEBUG_DECODE); + _content->film()->log()->log (String::compose ("ADS receives %1 %2", time, data->frames ()), LogEntry::TYPE_DEBUG_DECODE); if (_resampler) { data = _resampler->run (data); diff --git a/src/lib/config.cc b/src/lib/config.cc index 64d794b36..f00d8d1e5 100644 --- a/src/lib/config.cc +++ b/src/lib/config.cc @@ -98,7 +98,7 @@ Config::set_defaults () _check_for_updates = false; _check_for_test_updates = false; _maximum_j2k_bandwidth = 250000000; - _log_types = Log::TYPE_GENERAL | Log::TYPE_WARNING | Log::TYPE_ERROR; + _log_types = LogEntry::TYPE_GENERAL | LogEntry::TYPE_WARNING | LogEntry::TYPE_ERROR; _automatic_audio_analysis = false; #ifdef DCPOMATIC_WINDOWS _win32_console = false; @@ -234,7 +234,7 @@ Config::read () _maximum_j2k_bandwidth = f.optional_number_child ("MaximumJ2KBandwidth").get_value_or (250000000); _allow_any_dcp_frame_rate = f.optional_bool_child ("AllowAnyDCPFrameRate").get_value_or (false); - _log_types = f.optional_number_child ("LogTypes").get_value_or (Log::TYPE_GENERAL | Log::TYPE_WARNING | Log::TYPE_ERROR); + _log_types = f.optional_number_child ("LogTypes").get_value_or (LogEntry::TYPE_GENERAL | LogEntry::TYPE_WARNING | LogEntry::TYPE_ERROR); _automatic_audio_analysis = f.optional_bool_child ("AutomaticAudioAnalysis").get_value_or (false); #ifdef DCPOMATIC_WINDOWS _win32_console = f.optional_bool_child ("Win32Console").get_value_or (false); diff --git a/src/lib/cross.cc b/src/lib/cross.cc index 2689be2c2..9ca3fe2b0 100644 --- a/src/lib/cross.cc +++ b/src/lib/cross.cc @@ -46,9 +46,9 @@ #include "i18n.h" -#define LOG_GENERAL(...) log->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL); -#define LOG_ERROR(...) log->log (String::compose (__VA_ARGS__), Log::TYPE_ERROR); -#define LOG_ERROR_NC(...) log->log (__VA_ARGS__, Log::TYPE_ERROR); +#define LOG_GENERAL(...) log->log (String::compose (__VA_ARGS__), LogEntry::TYPE_GENERAL); +#define LOG_ERROR(...) log->log (String::compose (__VA_ARGS__), LogEntry::TYPE_ERROR); +#define LOG_ERROR_NC(...) log->log (__VA_ARGS__, LogEntry::TYPE_ERROR); using std::pair; using std::list; diff --git a/src/lib/dcp_video.cc b/src/lib/dcp_video.cc index 82206c045..35cc282fd 100644 --- a/src/lib/dcp_video.cc +++ b/src/lib/dcp_video.cc @@ -51,9 +51,9 @@ #include #include -#define LOG_GENERAL(...) _log->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL); -#define LOG_DEBUG_ENCODE(...) _log->log (String::compose (__VA_ARGS__), Log::TYPE_DEBUG_ENCODE); -#define LOG_TIMING(...) _log->microsecond_log (String::compose (__VA_ARGS__), Log::TYPE_TIMING); +#define LOG_GENERAL(...) _log->log (String::compose (__VA_ARGS__), LogEntry::TYPE_GENERAL); +#define LOG_DEBUG_ENCODE(...) _log->log (String::compose (__VA_ARGS__), LogEntry::TYPE_DEBUG_ENCODE); +#define LOG_TIMING(...) _log->log (String::compose (__VA_ARGS__), LogEntry::TYPE_TIMING); #include "i18n.h" diff --git a/src/lib/encoded_log_entry.cc b/src/lib/encoded_log_entry.cc new file mode 100644 index 000000000..a81803418 --- /dev/null +++ b/src/lib/encoded_log_entry.cc @@ -0,0 +1,49 @@ +/* + Copyright (C) 2015 Carl Hetherington + + This program is free software; you can redistribute it and/or modify + it under the terms of the GNU General Public License as published by + the Free Software Foundation; either version 2 of the License, or + (at your option) any later version. + + This program is distributed in the hope that it will be useful, + but WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + GNU General Public License for more details. + + You should have received a copy of the GNU General Public License + along with this program; if not, write to the Free Software + Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA. + +*/ + +#include "encoded_log_entry.h" +#include "safe_stringstream.h" + +using std::string; +using std::fixed; + +EncodedLogEntry::EncodedLogEntry (int frame, string ip, double receive, double encode, double send) + : LogEntry (LogEntry::TYPE_GENERAL) + , _frame (frame) + , _ip (ip) + , _receive (receive) + , _encode (encode) + , _send (send) +{ + +} + +string +EncodedLogEntry::message () const +{ + SafeStringStream m; + m.precision (2); + m << fixed + << "Encoded frame " << _frame << " from " << _ip << ": " + << "receive " << _receive << "s " + << "encode " << _encode << "s " + << "send " << _send << "s."; + + return m.str (); +} diff --git a/src/lib/encoded_log_entry.h b/src/lib/encoded_log_entry.h new file mode 100644 index 000000000..0037d8b1b --- /dev/null +++ b/src/lib/encoded_log_entry.h @@ -0,0 +1,35 @@ +/* + Copyright (C) 2015 Carl Hetherington + + This program is free software; you can redistribute it and/or modify + it under the terms of the GNU General Public License as published by + the Free Software Foundation; either version 2 of the License, or + (at your option) any later version. + + This program is distributed in the hope that it will be useful, + but WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + GNU General Public License for more details. + + You should have received a copy of the GNU General Public License + along with this program; if not, write to the Free Software + Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA. + +*/ + +#include "log_entry.h" + +class EncodedLogEntry : public LogEntry +{ +public: + EncodedLogEntry (int frame, std::string ip, double receive, double encode, double send); + + std::string message () const; + +private: + int _frame; + std::string _ip; + double _receive; + double _encode; + double _send; +}; diff --git a/src/lib/encoder.cc b/src/lib/encoder.cc index ef58ca09e..f7a66708e 100644 --- a/src/lib/encoder.cc +++ b/src/lib/encoder.cc @@ -42,10 +42,10 @@ #include "i18n.h" -#define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL); -#define LOG_GENERAL_NC(...) _film->log()->log (__VA_ARGS__, Log::TYPE_GENERAL); -#define LOG_ERROR(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_ERROR); -#define LOG_TIMING(...) _film->log()->microsecond_log (String::compose (__VA_ARGS__), Log::TYPE_TIMING); +#define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_GENERAL); +#define LOG_GENERAL_NC(...) _film->log()->log (__VA_ARGS__, LogEntry::TYPE_GENERAL); +#define LOG_ERROR(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_ERROR); +#define LOG_TIMING(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_TIMING); using std::list; using std::cout; diff --git a/src/lib/environment_info.cc b/src/lib/environment_info.cc index 364973ff8..ecb80fc14 100644 --- a/src/lib/environment_info.cc +++ b/src/lib/environment_info.cc @@ -42,8 +42,8 @@ extern "C" { #include "i18n.h" -#define LOG_GENERAL(...) log->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL); -#define LOG_GENERAL_NC(...) log->log (__VA_ARGS__, Log::TYPE_GENERAL); +#define LOG_GENERAL(...) log->log (String::compose (__VA_ARGS__), LogEntry::TYPE_GENERAL); +#define LOG_GENERAL_NC(...) log->log (__VA_ARGS__, LogEntry::TYPE_GENERAL); using std::string; using std::list; diff --git a/src/lib/ffmpeg.cc b/src/lib/ffmpeg.cc index 29dee2c86..6103ccd50 100644 --- a/src/lib/ffmpeg.cc +++ b/src/lib/ffmpeg.cc @@ -99,7 +99,7 @@ FFmpeg::ffmpeg_log_callback (void* ptr, int level, const char* fmt, va_list vl) if (log) { string str (line); boost::algorithm::trim (str); - log->log (String::compose ("FFmpeg: %1", str), Log::TYPE_GENERAL); + log->log (String::compose ("FFmpeg: %1", str), LogEntry::TYPE_GENERAL); } else { cerr << line; } diff --git a/src/lib/ffmpeg_content.cc b/src/lib/ffmpeg_content.cc index 84e474a4b..2c2d36a98 100644 --- a/src/lib/ffmpeg_content.cc +++ b/src/lib/ffmpeg_content.cc @@ -42,7 +42,7 @@ extern "C" { #include "i18n.h" -#define LOG_GENERAL(...) film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL); +#define LOG_GENERAL(...) film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_GENERAL); using std::string; using std::vector; diff --git a/src/lib/ffmpeg_decoder.cc b/src/lib/ffmpeg_decoder.cc index 3fdb2f2a9..83bce1830 100644 --- a/src/lib/ffmpeg_decoder.cc +++ b/src/lib/ffmpeg_decoder.cc @@ -47,10 +47,10 @@ extern "C" { #include "i18n.h" -#define LOG_GENERAL(...) _log->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL); -#define LOG_ERROR(...) _log->log (String::compose (__VA_ARGS__), Log::TYPE_ERROR); -#define LOG_WARNING_NC(...) _log->log (__VA_ARGS__, Log::TYPE_WARNING); -#define LOG_WARNING(...) _log->log (String::compose (__VA_ARGS__), Log::TYPE_WARNING); +#define LOG_GENERAL(...) _log->log (String::compose (__VA_ARGS__), LogEntry::TYPE_GENERAL); +#define LOG_ERROR(...) _log->log (String::compose (__VA_ARGS__), LogEntry::TYPE_ERROR); +#define LOG_WARNING_NC(...) _log->log (__VA_ARGS__, LogEntry::TYPE_WARNING); +#define LOG_WARNING(...) _log->log (String::compose (__VA_ARGS__), LogEntry::TYPE_WARNING); using std::cout; using std::vector; diff --git a/src/lib/file_log.cc b/src/lib/file_log.cc index b3c9797c9..1557bbd94 100644 --- a/src/lib/file_log.cc +++ b/src/lib/file_log.cc @@ -25,6 +25,7 @@ using std::cout; using std::string; using std::max; +using boost::shared_ptr; /** @param file Filename to write log to */ FileLog::FileLog (boost::filesystem::path file) @@ -34,15 +35,15 @@ FileLog::FileLog (boost::filesystem::path file) } void -FileLog::do_log (string m) +FileLog::do_log (shared_ptr entry) { FILE* f = fopen_boost (_file, "a"); if (!f) { - cout << "(could not log to " << _file.string() << "): " << m << "\n"; + cout << "(could not log to " << _file.string() << "): " << entry.get() << "\n"; return; } - fprintf (f, "%s\n", m.c_str ()); + fprintf (f, "%s\n", entry->get().c_str ()); fclose (f); } diff --git a/src/lib/file_log.h b/src/lib/file_log.h index 1051ad1f9..649992000 100644 --- a/src/lib/file_log.h +++ b/src/lib/file_log.h @@ -27,7 +27,7 @@ public: std::string head_and_tail (int amount = 1024) const; private: - void do_log (std::string m); + void do_log (boost::shared_ptr entry); /** filename to write to */ boost::filesystem::path _file; }; diff --git a/src/lib/film.cc b/src/lib/film.cc index 37d5c3447..a50aad817 100644 --- a/src/lib/film.cc +++ b/src/lib/film.cc @@ -86,8 +86,8 @@ using boost::dynamic_pointer_cast; using boost::optional; using boost::is_any_of; -#define LOG_GENERAL(...) log()->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL); -#define LOG_GENERAL_NC(...) log()->log (__VA_ARGS__, Log::TYPE_GENERAL); +#define LOG_GENERAL(...) log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_GENERAL); +#define LOG_GENERAL_NC(...) log()->log (__VA_ARGS__, LogEntry::TYPE_GENERAL); /* 5 -> 6 * AudioMapping XML changed. diff --git a/src/lib/job.cc b/src/lib/job.cc index 42d6160c7..35f583408 100644 --- a/src/lib/job.cc +++ b/src/lib/job.cc @@ -42,7 +42,7 @@ using boost::shared_ptr; using boost::optional; using boost::function; -#define LOG_ERROR_NC(...) _film->log()->log (__VA_ARGS__, Log::TYPE_ERROR); +#define LOG_ERROR_NC(...) _film->log()->log (__VA_ARGS__, LogEntry::TYPE_ERROR); /** @param film Associated film, or 0 */ Job::Job (shared_ptr film) @@ -325,7 +325,7 @@ Job::set_error (string s, string d) if (_film) { LOG_ERROR_NC (s); LOG_ERROR_NC (d); - _film->log()->log (String::compose ("Error in job: %1 (%2)", s, d), Log::TYPE_ERROR); + _film->log()->log (String::compose ("Error in job: %1 (%2)", s, d), LogEntry::TYPE_ERROR); } boost::mutex::scoped_lock lm (_state_mutex); diff --git a/src/lib/log.cc b/src/lib/log.cc index 2e5cc54e1..0f7a59ff8 100644 --- a/src/lib/log.cc +++ b/src/lib/log.cc @@ -1,5 +1,5 @@ /* - Copyright (C) 2012 Carl Hetherington + Copyright (C) 2012-2015 Carl Hetherington This program is free software; you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -25,19 +25,14 @@ #include "cross.h" #include "config.h" #include "safe_stringstream.h" +#include "string_log_entry.h" #include #include #include "i18n.h" -using namespace std; - -int const Log::TYPE_GENERAL = 0x1; -int const Log::TYPE_WARNING = 0x2; -int const Log::TYPE_ERROR = 0x4; -int const Log::TYPE_DEBUG_DECODE = 0x8; -int const Log::TYPE_DEBUG_ENCODE = 0x10; -int const Log::TYPE_TIMING = 0x20; +using std::string; +using boost::shared_ptr; Log::Log () : _types (0) @@ -52,50 +47,29 @@ Log::config_changed () set_types (Config::instance()->log_types ()); } -/** @param n String to log */ void -Log::log (string message, int type) +Log::log (shared_ptr e) { boost::mutex::scoped_lock lm (_mutex); - if ((_types & type) == 0) { + if ((_types & e->type()) == 0) { return; } - time_t t; - time (&t); - string a = ctime (&t); - - SafeStringStream s; - s << a.substr (0, a.length() - 1) << N_(": "); - - if (type & TYPE_ERROR) { - s << "ERROR: "; - } - - if (type & TYPE_WARNING) { - s << "WARNING: "; - } - - s << message; - do_log (s.str ()); + do_log (e); } +/** @param n String to log */ void -Log::microsecond_log (string m, int t) +Log::log (string message, int type) { boost::mutex::scoped_lock lm (_mutex); - if ((_types & t) == 0) { + if ((_types & type) == 0) { return; } - struct timeval tv; - gettimeofday (&tv, 0); - - SafeStringStream s; - s << tv.tv_sec << N_(":") << tv.tv_usec << N_(" ") << m; - do_log (s.str ()); + do_log (shared_ptr (new StringLogEntry (type, message))); } void @@ -103,13 +77,13 @@ Log::dcp_log (dcp::NoteType type, string m) { switch (type) { case dcp::DCP_PROGRESS: - log (m, TYPE_GENERAL); + do_log (shared_ptr (new StringLogEntry (LogEntry::TYPE_GENERAL, m))); break; case dcp::DCP_ERROR: - log (m, TYPE_ERROR); + do_log (shared_ptr (new StringLogEntry (LogEntry::TYPE_ERROR, m))); break; case dcp::DCP_NOTE: - log (m, TYPE_WARNING); + do_log (shared_ptr (new StringLogEntry (LogEntry::TYPE_WARNING, m))); break; } } diff --git a/src/lib/log.h b/src/lib/log.h index 2acef6601..2c44f32ce 100644 --- a/src/lib/log.h +++ b/src/lib/log.h @@ -24,6 +24,7 @@ * @brief A very simple logging class. */ +#include "log_entry.h" #include #include #include @@ -39,15 +40,8 @@ public: Log (); virtual ~Log () {} - static const int TYPE_GENERAL; - static const int TYPE_WARNING; - static const int TYPE_ERROR; - static const int TYPE_DEBUG_DECODE; - static const int TYPE_DEBUG_ENCODE; - static const int TYPE_TIMING; - + void log (boost::shared_ptr entry); void log (std::string message, int type); - void microsecond_log (std::string message, int type); void dcp_log (dcp::NoteType type, std::string message); void set_types (int types); @@ -63,7 +57,7 @@ protected: mutable boost::mutex _mutex; private: - virtual void do_log (std::string m) = 0; + virtual void do_log (boost::shared_ptr entry) = 0; void config_changed (); /** bit-field of log types which should be put into the log (others are ignored) */ diff --git a/src/lib/log_entry.cc b/src/lib/log_entry.cc new file mode 100644 index 000000000..9b399e4b6 --- /dev/null +++ b/src/lib/log_entry.cc @@ -0,0 +1,70 @@ +/* + Copyright (C) 2015 Carl Hetherington + + This program is free software; you can redistribute it and/or modify + it under the terms of the GNU General Public License as published by + the Free Software Foundation; either version 2 of the License, or + (at your option) any later version. + + This program is distributed in the hope that it will be useful, + but WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + GNU General Public License for more details. + + You should have received a copy of the GNU General Public License + along with this program; if not, write to the Free Software + Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA. + +*/ + +#include "log_entry.h" +#include "safe_stringstream.h" + +#include "i18n.h" + +int const LogEntry::TYPE_GENERAL = 0x1; +int const LogEntry::TYPE_WARNING = 0x2; +int const LogEntry::TYPE_ERROR = 0x4; +int const LogEntry::TYPE_DEBUG_DECODE = 0x8; +int const LogEntry::TYPE_DEBUG_ENCODE = 0x10; +int const LogEntry::TYPE_TIMING = 0x20; + +using std::string; + +LogEntry::LogEntry (int type) + : _type (type) +{ + gettimeofday (&_time, 0); +} + +string +LogEntry::get () const +{ + SafeStringStream s; + if (_type & TYPE_TIMING) { + s << _time.tv_sec << ":" << _time.tv_usec; + } else { + char buffer[64]; + struct tm* t = localtime (&_time.tv_sec); + strftime (buffer, 64, "%c", t); + string a (buffer); + s << a.substr (0, a.length() - 1) << N_(": "); + } + + if (_type & TYPE_ERROR) { + s << "ERROR: "; + } + + if (_type & TYPE_WARNING) { + s << "WARNING: "; + } + + s << message (); + return s.str (); +} + +double +LogEntry::seconds () const +{ + return _time.tv_sec + double (_time.tv_usec / 1000000); +} diff --git a/src/lib/log_entry.h b/src/lib/log_entry.h new file mode 100644 index 000000000..29c709085 --- /dev/null +++ b/src/lib/log_entry.h @@ -0,0 +1,51 @@ +/* + Copyright (C) 2015 Carl Hetherington + + This program is free software; you can redistribute it and/or modify + it under the terms of the GNU General Public License as published by + the Free Software Foundation; either version 2 of the License, or + (at your option) any later version. + + This program is distributed in the hope that it will be useful, + but WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + GNU General Public License for more details. + + You should have received a copy of the GNU General Public License + along with this program; if not, write to the Free Software + Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA. + +*/ + +#ifndef DCPOMATIC_LOG_ENTRY_H +#define DCPOMATIC_LOG_ENTRY_H + +#include + +class LogEntry +{ +public: + + static const int TYPE_GENERAL; + static const int TYPE_WARNING; + static const int TYPE_ERROR; + static const int TYPE_DEBUG_DECODE; + static const int TYPE_DEBUG_ENCODE; + static const int TYPE_TIMING; + + LogEntry (int type); + + virtual std::string message () const = 0; + + int type () const { + return _type; + } + std::string get () const; + double seconds () const; + +private: + struct timeval _time; + int _type; +}; + +#endif diff --git a/src/lib/null_log.h b/src/lib/null_log.h index 304c5ec1c..6e29ad3ab 100644 --- a/src/lib/null_log.h +++ b/src/lib/null_log.h @@ -27,5 +27,5 @@ public: } private: - void do_log (std::string) {} + void do_log (boost::shared_ptr) {} }; diff --git a/src/lib/player.cc b/src/lib/player.cc index d316711f7..0606a9340 100644 --- a/src/lib/player.cc +++ b/src/lib/player.cc @@ -57,7 +57,7 @@ #include "i18n.h" -#define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL); +#define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_GENERAL); using std::list; using std::cout; diff --git a/src/lib/server.cc b/src/lib/server.cc index f0b2d9816..5d85d8800 100644 --- a/src/lib/server.cc +++ b/src/lib/server.cc @@ -35,6 +35,7 @@ #include "raw_convert.h" #include "compose.hpp" #include "log.h" +#include "encoded_log_entry.h" #include #include #include @@ -46,10 +47,10 @@ #include "i18n.h" -#define LOG_GENERAL(...) _log->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL); -#define LOG_GENERAL_NC(...) _log->log (__VA_ARGS__, Log::TYPE_GENERAL); -#define LOG_ERROR(...) _log->log (String::compose (__VA_ARGS__), Log::TYPE_ERROR); -#define LOG_ERROR_NC(...) _log->log (__VA_ARGS__, Log::TYPE_ERROR); +#define LOG_GENERAL(...) _log->log (String::compose (__VA_ARGS__), LogEntry::TYPE_GENERAL); +#define LOG_GENERAL_NC(...) _log->log (__VA_ARGS__, LogEntry::TYPE_GENERAL); +#define LOG_ERROR(...) _log->log (String::compose (__VA_ARGS__), LogEntry::TYPE_ERROR); +#define LOG_ERROR_NC(...) _log->log (__VA_ARGS__, LogEntry::TYPE_ERROR); using std::string; using std::vector; @@ -187,19 +188,20 @@ Server::worker_thread () struct timeval end; gettimeofday (&end, 0); - SafeStringStream message; - message.precision (2); - message << fixed - << "Encoded frame " << frame << " from " << ip << ": " - << "receive " << (seconds(after_read) - seconds(start)) << "s " - << "encode " << (seconds(after_encode) - seconds(after_read)) << "s " - << "send " << (seconds(end) - seconds(after_encode)) << "s."; + shared_ptr e ( + new EncodedLogEntry ( + frame, ip, + seconds(after_read) - seconds(start), + seconds(after_encode) - seconds(after_read), + seconds(end) - seconds(after_encode) + ) + ); if (_verbose) { - cout << message.str() << "\n"; + cout << e->get() << "\n"; } - LOG_GENERAL_NC (message.str ()); + _log->log (e); } _full_condition.notify_all (); diff --git a/src/lib/string_log_entry.cc b/src/lib/string_log_entry.cc new file mode 100644 index 000000000..9763726ff --- /dev/null +++ b/src/lib/string_log_entry.cc @@ -0,0 +1,32 @@ +/* + Copyright (C) 2015 Carl Hetherington + + This program is free software; you can redistribute it and/or modify + it under the terms of the GNU General Public License as published by + the Free Software Foundation; either version 2 of the License, or + (at your option) any later version. + + This program is distributed in the hope that it will be useful, + but WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + GNU General Public License for more details. + + You should have received a copy of the GNU General Public License + along with this program; if not, write to the Free Software + Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA. + +*/ + +#include "string_log_entry.h" +#include "safe_stringstream.h" + +#include "i18n.h" + +using std::string; + +StringLogEntry::StringLogEntry (int type, string message) + : LogEntry (type) + , _message (message) +{ + +} diff --git a/src/lib/string_log_entry.h b/src/lib/string_log_entry.h new file mode 100644 index 000000000..365463f13 --- /dev/null +++ b/src/lib/string_log_entry.h @@ -0,0 +1,34 @@ +/* + Copyright (C) 2015 Carl Hetherington + + This program is free software; you can redistribute it and/or modify + it under the terms of the GNU General Public License as published by + the Free Software Foundation; either version 2 of the License, or + (at your option) any later version. + + This program is distributed in the hope that it will be useful, + but WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + GNU General Public License for more details. + + You should have received a copy of the GNU General Public License + along with this program; if not, write to the Free Software + Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA. + +*/ + +#include "log_entry.h" +#include + +class StringLogEntry : public LogEntry +{ +public: + StringLogEntry (int type, std::string message); + + std::string message () const { + return _message; + } + +private: + std::string _message; +}; diff --git a/src/lib/transcode_job.cc b/src/lib/transcode_job.cc index f10078f3c..7d11d51a9 100644 --- a/src/lib/transcode_job.cc +++ b/src/lib/transcode_job.cc @@ -32,8 +32,8 @@ #include "i18n.h" -#define LOG_GENERAL_NC(...) _film->log()->log (__VA_ARGS__, Log::TYPE_GENERAL); -#define LOG_ERROR_NC(...) _film->log()->log (__VA_ARGS__, Log::TYPE_ERROR); +#define LOG_GENERAL_NC(...) _film->log()->log (__VA_ARGS__, LogEntry::TYPE_GENERAL); +#define LOG_ERROR_NC(...) _film->log()->log (__VA_ARGS__, LogEntry::TYPE_ERROR); using std::string; using std::fixed; diff --git a/src/lib/upload_job.cc b/src/lib/upload_job.cc index 44114b8a8..90ebafd52 100644 --- a/src/lib/upload_job.cc +++ b/src/lib/upload_job.cc @@ -32,7 +32,7 @@ #include "i18n.h" -#define LOG_GENERAL_NC(...) _film->log()->log (__VA_ARGS__, Log::TYPE_GENERAL); +#define LOG_GENERAL_NC(...) _film->log()->log (__VA_ARGS__, LogEntry::TYPE_GENERAL); using std::string; using std::min; diff --git a/src/lib/video_content.cc b/src/lib/video_content.cc index 5a2bef1a0..ff54c4014 100644 --- a/src/lib/video_content.cc +++ b/src/lib/video_content.cc @@ -38,7 +38,7 @@ #include "i18n.h" -#define LOG_GENERAL(...) film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL); +#define LOG_GENERAL(...) film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_GENERAL); int const VideoContentProperty::VIDEO_SIZE = 0; int const VideoContentProperty::VIDEO_FRAME_RATE = 1; diff --git a/src/lib/video_decoder.cc b/src/lib/video_decoder.cc index e87fa2eb1..88f88c129 100644 --- a/src/lib/video_decoder.cc +++ b/src/lib/video_decoder.cc @@ -75,7 +75,7 @@ VideoDecoder::get_video (Frame frame, bool accurate) one after the end of _decoded_video we need to seek. */ - _video_content->film()->log()->log (String::compose ("VD has request for %1", frame), Log::TYPE_DEBUG_DECODE); + _video_content->film()->log()->log (String::compose ("VD has request for %1", frame), LogEntry::TYPE_DEBUG_DECODE); if (_decoded_video.empty() || frame < _decoded_video.front().frame || frame > (_decoded_video.back().frame + 1)) { seek (ContentTime::from_frames (frame, _video_content->video_frame_rate()), accurate); @@ -240,7 +240,7 @@ VideoDecoder::video (shared_ptr image, Frame frame) return; } - _video_content->film()->log()->log (String::compose ("VD receives %1", frame), Log::TYPE_DEBUG_DECODE); + _video_content->film()->log()->log (String::compose ("VD receives %1", frame), LogEntry::TYPE_DEBUG_DECODE); /* We may receive the same frame index twice for 3D, and we need to know when that happens. diff --git a/src/lib/writer.cc b/src/lib/writer.cc index 3f856737b..0653daa57 100644 --- a/src/lib/writer.cc +++ b/src/lib/writer.cc @@ -55,13 +55,13 @@ #include "i18n.h" -#define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL); -#define LOG_GENERAL_NC(...) _film->log()->log (__VA_ARGS__, Log::TYPE_GENERAL); -#define LOG_DEBUG_ENCODE(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_DEBUG_ENCODE); -#define LOG_TIMING(...) _film->log()->microsecond_log (String::compose (__VA_ARGS__), Log::TYPE_TIMING); -#define LOG_WARNING_NC(...) _film->log()->log (__VA_ARGS__, Log::TYPE_WARNING); -#define LOG_WARNING(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_WARNING); -#define LOG_ERROR(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_ERROR); +#define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_GENERAL); +#define LOG_GENERAL_NC(...) _film->log()->log (__VA_ARGS__, LogEntry::TYPE_GENERAL); +#define LOG_DEBUG_ENCODE(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_DEBUG_ENCODE); +#define LOG_TIMING(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_TIMING); +#define LOG_WARNING_NC(...) _film->log()->log (__VA_ARGS__, LogEntry::TYPE_WARNING); +#define LOG_WARNING(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_WARNING); +#define LOG_ERROR(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_ERROR); /* OS X strikes again */ #undef set_key diff --git a/src/lib/wscript b/src/lib/wscript index bc61c87bf..6e06d6753 100644 --- a/src/lib/wscript +++ b/src/lib/wscript @@ -55,6 +55,7 @@ sources = """ dolby_cp750.cc emailer.cc encoder.cc + encoded_log_entry.cc environment_info.cc examine_content_job.cc exceptions.cc @@ -84,6 +85,7 @@ sources = """ job_manager.cc json_server.cc log.cc + log_entry.cc magick_image_proxy.cc md5_digester.cc mid_side_decoder.cc @@ -110,6 +112,7 @@ sources = """ sndfile_content.cc sndfile_decoder.cc sndfile_examiner.cc + string_log_entry.cc subrip.cc subrip_content.cc subrip_decoder.cc diff --git a/src/tools/dcpomatic_server.cc b/src/tools/dcpomatic_server.cc index 37fcc34cd..d87683280 100644 --- a/src/tools/dcpomatic_server.cc +++ b/src/tools/dcpomatic_server.cc @@ -20,23 +20,30 @@ #include "wx/wx_util.h" #include "wx/wx_signal_manager.h" #include "lib/util.h" +#include "lib/encoded_log_entry.h" #include "lib/server.h" #include "lib/config.h" #include "lib/log.h" +#include "lib/raw_convert.h" #include "lib/signaller.h" #include #include #include #include +#include #include using std::cout; using std::string; using std::exception; using std::list; +using std::fixed; +using std::setprecision; using boost::shared_ptr; using boost::thread; using boost::bind; +using boost::optional; +using boost::dynamic_pointer_cast; enum { ID_status = 1, @@ -46,7 +53,7 @@ enum { static int const log_lines = 32; -class MemoryLog : public Log, public Signaller +class ServerLog : public Log, public Signaller { public: @@ -63,24 +70,66 @@ public: return ""; } + float fps () const { + boost::mutex::scoped_lock lm (_state_mutex); + return _fps; + } + boost::signals2::signal Appended; boost::signals2::signal Removed; private: - void do_log (string m) + void do_log (shared_ptr entry) { - _log.push_back (m); - emit (boost::bind (boost::ref (Appended), m)); + time_t const s = entry->seconds (); + struct tm* local = localtime (&s); + if ( + !_last_time || + local->tm_yday != _last_time->tm_yday || + local->tm_year != _last_time->tm_year || + local->tm_hour != _last_time->tm_hour || + local->tm_min != _last_time->tm_min + ) { + char buffer[64]; + strftime (buffer, 64, "%c", local); + append (buffer); + } + + append (entry->message ()); if (_log.size() > log_lines) { emit (boost::bind (boost::ref (Removed), _log.front().length())); _log.pop_front (); } + _last_time = *local; + + shared_ptr encoded = dynamic_pointer_cast (entry); + if (encoded) { + _history.push_back (encoded->seconds ()); + if (_history.size() > 48) { + _history.pop_front (); + } + if (_history.size() > 2) { + boost::mutex::scoped_lock lm (_state_mutex); + _fps = _history.size() / (_history.back() - _history.front()); + } + } + } + + void append (string s) + { + _log.push_back (s); + emit (boost::bind (boost::ref (Appended), s)); } list _log; + optional _last_time; + std::list _history; + + mutable boost::mutex _state_mutex; + float _fps; }; -static shared_ptr memory_log (new MemoryLog); +static shared_ptr server_log (new ServerLog); class StatusDialog : public wxDialog { @@ -92,8 +141,14 @@ public: wxDEFAULT_DIALOG_STYLE | wxRESIZE_BORDER ) { - _sizer = new wxFlexGridSizer (1, DCPOMATIC_SIZER_GAP, DCPOMATIC_SIZER_GAP); - _sizer->AddGrowableCol (0, 1); + wxFlexGridSizer* state_sizer = new wxFlexGridSizer (2, DCPOMATIC_SIZER_GAP, DCPOMATIC_SIZER_GAP); + + add_label_to_sizer (state_sizer, this, _("Frames per second"), true); + _fps = new wxStaticText (this, wxID_ANY, wxT("")); + state_sizer->Add (_fps); + + wxFlexGridSizer* log_sizer = new wxFlexGridSizer (1, DCPOMATIC_SIZER_GAP, DCPOMATIC_SIZER_GAP); + log_sizer->AddGrowableCol (0, 1); wxClientDC dc (this); wxSize size = dc.GetTextExtent (wxT ("This is the length of the file label it should be quite long")); @@ -101,17 +156,24 @@ public: SetSize (700, height + DCPOMATIC_SIZER_GAP * 2); _text = new wxTextCtrl ( - this, wxID_ANY, std_to_wx (memory_log->get()), wxDefaultPosition, wxSize (-1, height), + this, wxID_ANY, std_to_wx (server_log->get()), wxDefaultPosition, wxSize (-1, height), wxTE_READONLY | wxTE_MULTILINE ); - _sizer->Add (_text, 1, wxEXPAND | wxALL, DCPOMATIC_SIZER_GAP); + log_sizer->Add (_text, 1, wxEXPAND); - SetSizer (_sizer); - _sizer->Layout (); + wxBoxSizer* overall_sizer = new wxBoxSizer (wxVERTICAL); + overall_sizer->Add (state_sizer, 0, wxALL, DCPOMATIC_SIZER_GAP); + overall_sizer->Add (log_sizer, 1, wxEXPAND | wxALL, DCPOMATIC_SIZER_GAP); + SetSizer (overall_sizer); + overall_sizer->Layout (); + + Bind (wxEVT_TIMER, boost::bind (&StatusDialog::update_state, this)); + _timer.reset (new wxTimer (this)); + _timer->Start (1000); - memory_log->Appended.connect (bind (&StatusDialog::appended, this, _1)); - memory_log->Removed.connect (bind (&StatusDialog::removed, this, _1)); + server_log->Appended.connect (bind (&StatusDialog::appended, this, _1)); + server_log->Removed.connect (bind (&StatusDialog::removed, this, _1)); } private: @@ -125,8 +187,16 @@ private: _text->Remove (0, n + 1); } - wxFlexGridSizer* _sizer; + void update_state () + { + SafeStringStream s; + s << fixed << setprecision(1) << server_log->fps (); + _fps->SetLabel (std_to_wx (s.str())); + } + wxTextCtrl* _text; + wxStaticText* _fps; + boost::shared_ptr _timer; }; class TaskBarIcon : public wxTaskBarIcon @@ -218,7 +288,7 @@ private: void main_thread () try { - Server server (memory_log, false); + Server server (server_log, false); server.run (Config::instance()->num_local_encoding_threads ()); } catch (...) { store_current (); diff --git a/src/wx/config_dialog.cc b/src/wx/config_dialog.cc index 722fa59ce..f3dbaf6d9 100644 --- a/src/wx/config_dialog.cc +++ b/src/wx/config_dialog.cc @@ -1357,12 +1357,12 @@ private: checked_set (_maximum_j2k_bandwidth, config->maximum_j2k_bandwidth() / 1000000); checked_set (_allow_any_dcp_frame_rate, config->allow_any_dcp_frame_rate ()); checked_set (_only_servers_encode, config->only_servers_encode ()); - checked_set (_log_general, config->log_types() & Log::TYPE_GENERAL); - checked_set (_log_warning, config->log_types() & Log::TYPE_WARNING); - checked_set (_log_error, config->log_types() & Log::TYPE_ERROR); - checked_set (_log_timing, config->log_types() & Log::TYPE_TIMING); - checked_set (_log_debug_decode, config->log_types() & Log::TYPE_DEBUG_DECODE); - checked_set (_log_debug_encode, config->log_types() & Log::TYPE_DEBUG_ENCODE); + checked_set (_log_general, config->log_types() & LogEntry::TYPE_GENERAL); + checked_set (_log_warning, config->log_types() & LogEntry::TYPE_WARNING); + checked_set (_log_error, config->log_types() & LogEntry::TYPE_ERROR); + checked_set (_log_timing, config->log_types() & LogEntry::TYPE_TIMING); + checked_set (_log_debug_decode, config->log_types() & LogEntry::TYPE_DEBUG_DECODE); + checked_set (_log_debug_encode, config->log_types() & LogEntry::TYPE_DEBUG_ENCODE); #ifdef DCPOMATIC_WINDOWS checked_set (_win32_console, config->win32_console()); #endif @@ -1387,22 +1387,22 @@ private: { int types = 0; if (_log_general->GetValue ()) { - types |= Log::TYPE_GENERAL; + types |= LogEntry::TYPE_GENERAL; } if (_log_warning->GetValue ()) { - types |= Log::TYPE_WARNING; + types |= LogEntry::TYPE_WARNING; } if (_log_error->GetValue ()) { - types |= Log::TYPE_ERROR; + types |= LogEntry::TYPE_ERROR; } if (_log_timing->GetValue ()) { - types |= Log::TYPE_TIMING; + types |= LogEntry::TYPE_TIMING; } if (_log_debug_decode->GetValue ()) { - types |= Log::TYPE_DEBUG_DECODE; + types |= LogEntry::TYPE_DEBUG_DECODE; } if (_log_debug_encode->GetValue ()) { - types |= Log::TYPE_DEBUG_ENCODE; + types |= LogEntry::TYPE_DEBUG_ENCODE; } Config::instance()->set_log_types (types); } -- 2.30.2