From ce55f15c02a9457f86d197ede36919343579c24a Mon Sep 17 00:00:00 2001 From: badaix Date: Mon, 24 Jul 2017 18:59:49 +0200 Subject: [PATCH] update logger --- client/Makefile | 2 +- client/browseZeroConf/browseAvahi.cpp | 34 +- client/browseZeroConf/browseBonjour.cpp | 2 +- client/clientConnection.cpp | 28 +- client/controller.cpp | 25 +- client/decoder/flacDecoder.cpp | 8 +- client/decoder/oggDecoder.cpp | 6 +- client/player/alsaPlayer.cpp | 28 +- client/player/coreAudioPlayer.cpp | 12 +- client/player/openslPlayer.cpp | 26 +- client/player/player.cpp | 2 +- client/snapClient.cpp | 21 +- client/stream.cpp | 46 +- client/timeProvider.cpp | 4 +- common/log.cpp | 132 ---- common/log.h | 759 +++++++++++++++++++++- common/sampleFormat.cpp | 2 +- server/Makefile | 2 +- server/config.cpp | 8 +- server/controlServer.cpp | 6 +- server/controlSession.cpp | 20 +- server/encoder/flacEncoder.cpp | 6 +- server/encoder/oggEncoder.cpp | 6 +- server/publishZeroConf/publishAvahi.cpp | 22 +- server/publishZeroConf/publishBonjour.cpp | 14 +- server/snapServer.cpp | 19 +- server/streamServer.cpp | 42 +- server/streamSession.cpp | 24 +- server/streamreader/airplayStream.cpp | 8 +- server/streamreader/fileStream.cpp | 6 +- server/streamreader/pcmStream.cpp | 6 +- server/streamreader/pipeStream.cpp | 4 +- server/streamreader/processStream.cpp | 4 +- server/streamreader/spotifyStream.cpp | 6 +- server/streamreader/streamManager.cpp | 4 +- server/streamreader/streamUri.cpp | 12 +- 36 files changed, 967 insertions(+), 389 deletions(-) delete mode 100644 common/log.cpp diff --git a/client/Makefile b/client/Makefile index 907974c1..bc84bdaa 100644 --- a/client/Makefile +++ b/client/Makefile @@ -31,7 +31,7 @@ endif CXXFLAGS += $(ADD_CFLAGS) -std=c++0x -Wall -Wno-unused-function -O3 -DASIO_STANDALONE -DVERSION=\"$(VERSION)\" -I. -I.. -isystem ../externals/asio/asio/include -I../externals/popl/include -OBJ = snapClient.o stream.o clientConnection.o timeProvider.o player/player.o decoder/pcmDecoder.o decoder/oggDecoder.o decoder/flacDecoder.o controller.o ../message/pcmChunk.o ../common/log.o ../common/sampleFormat.o +OBJ = snapClient.o stream.o clientConnection.o timeProvider.o player/player.o decoder/pcmDecoder.o decoder/oggDecoder.o decoder/flacDecoder.o controller.o ../message/pcmChunk.o ../common/sampleFormat.o ifeq ($(ENDIAN), BIG) CXXFLAGS += -DIS_BIG_ENDIAN diff --git a/client/browseZeroConf/browseAvahi.cpp b/client/browseZeroConf/browseAvahi.cpp index d4756e4b..b8f97ee4 100755 --- a/client/browseZeroConf/browseAvahi.cpp +++ b/client/browseZeroConf/browseAvahi.cpp @@ -80,14 +80,14 @@ void BrowseAvahi::resolve_callback( switch (event) { case AVAHI_RESOLVER_FAILURE: - logE << "(Resolver) Failed to resolve service '" << name << "' of type '" << type << "' in domain '" << domain << "': " << avahi_strerror(avahi_client_errno(avahi_service_resolver_get_client(r))) << "\n"; + LOG(ERROR) << "(Resolver) Failed to resolve service '" << name << "' of type '" << type << "' in domain '" << domain << "': " << avahi_strerror(avahi_client_errno(avahi_service_resolver_get_client(r))) << "\n"; break; case AVAHI_RESOLVER_FOUND: { char a[AVAHI_ADDRESS_STR_MAX], *t; - logO << "Service '" << name << "' of type '" << type << "' in domain '" << domain << "':\n"; + LOG(INFO) << "Service '" << name << "' of type '" << type << "' in domain '" << domain << "':\n"; avahi_address_snprint(a, sizeof(a), address); browseAvahi->result_.host_ = host_name; @@ -97,15 +97,15 @@ void BrowseAvahi::resolve_callback( browseAvahi->result_.valid_ = true; t = avahi_string_list_to_string(txt); - logO << "\t" << host_name << ":" << port << " (" << a << ")\n"; - logD << "\tTXT=" << t << "\n"; - logD << "\tProto=" << (int)protocol << "\n"; - logD << "\tcookie is " << avahi_string_list_get_service_cookie(txt) << "\n"; - logD << "\tis_local: " << !!(flags & AVAHI_LOOKUP_RESULT_LOCAL) << "\n"; - logD << "\tour_own: " << !!(flags & AVAHI_LOOKUP_RESULT_OUR_OWN) << "\n"; - logD << "\twide_area: " << !!(flags & AVAHI_LOOKUP_RESULT_WIDE_AREA) << "\n"; - logD << "\tmulticast: " << !!(flags & AVAHI_LOOKUP_RESULT_MULTICAST) << "\n"; - logD << "\tcached: " << !!(flags & AVAHI_LOOKUP_RESULT_CACHED) << "\n"; + LOG(INFO) << "\t" << host_name << ":" << port << " (" << a << ")\n"; + LOG(DEBUG) << "\tTXT=" << t << "\n"; + LOG(DEBUG) << "\tProto=" << (int)protocol << "\n"; + LOG(DEBUG) << "\tcookie is " << avahi_string_list_get_service_cookie(txt) << "\n"; + LOG(DEBUG) << "\tis_local: " << !!(flags & AVAHI_LOOKUP_RESULT_LOCAL) << "\n"; + LOG(DEBUG) << "\tour_own: " << !!(flags & AVAHI_LOOKUP_RESULT_OUR_OWN) << "\n"; + LOG(DEBUG) << "\twide_area: " << !!(flags & AVAHI_LOOKUP_RESULT_WIDE_AREA) << "\n"; + LOG(DEBUG) << "\tmulticast: " << !!(flags & AVAHI_LOOKUP_RESULT_MULTICAST) << "\n"; + LOG(DEBUG) << "\tcached: " << !!(flags & AVAHI_LOOKUP_RESULT_CACHED) << "\n"; avahi_free(t); } } @@ -135,12 +135,12 @@ void BrowseAvahi::browse_callback( switch (event) { case AVAHI_BROWSER_FAILURE: - logE << "(Browser) " << avahi_strerror(avahi_client_errno(avahi_service_browser_get_client(b))) << "\n"; + LOG(ERROR) << "(Browser) " << avahi_strerror(avahi_client_errno(avahi_service_browser_get_client(b))) << "\n"; avahi_simple_poll_quit(simple_poll); return; case AVAHI_BROWSER_NEW: - logO << "(Browser) NEW: service '" << name << "' of type '" << type << "' in domain '" << domain << "'\n"; + LOG(INFO) << "(Browser) NEW: service '" << name << "' of type '" << type << "' in domain '" << domain << "'\n"; /* We ignore the returned resolver object. In the callback function we free it. If the server is terminated before @@ -148,17 +148,17 @@ void BrowseAvahi::browse_callback( the resolver for us. */ if (!(avahi_service_resolver_new(browseAvahi->client_, interface, protocol, name, type, domain, AVAHI_PROTO_UNSPEC, (AvahiLookupFlags)0, resolve_callback, userdata))) - logE << "Failed to resolve service '" << name << "': " << avahi_strerror(avahi_client_errno(browseAvahi->client_)) << "\n"; + LOG(ERROR) << "Failed to resolve service '" << name << "': " << avahi_strerror(avahi_client_errno(browseAvahi->client_)) << "\n"; break; case AVAHI_BROWSER_REMOVE: - logO << "(Browser) REMOVE: service '" << name << "' of type '" << type << "' in domain '" << domain << "'\n"; + LOG(INFO) << "(Browser) REMOVE: service '" << name << "' of type '" << type << "' in domain '" << domain << "'\n"; break; case AVAHI_BROWSER_ALL_FOR_NOW: case AVAHI_BROWSER_CACHE_EXHAUSTED: - logO << "(Browser) " << (event == AVAHI_BROWSER_CACHE_EXHAUSTED ? "CACHE_EXHAUSTED" : "ALL_FOR_NOW") << "\n"; + LOG(INFO) << "(Browser) " << (event == AVAHI_BROWSER_CACHE_EXHAUSTED ? "CACHE_EXHAUSTED" : "ALL_FOR_NOW") << "\n"; break; } } @@ -173,7 +173,7 @@ void BrowseAvahi::client_callback(AvahiClient *c, AvahiClientState state, AVAHI_ if (state == AVAHI_CLIENT_FAILURE) { - logE << "Server connection failure: " << avahi_strerror(avahi_client_errno(c)) << "\n"; + LOG(ERROR) << "Server connection failure: " << avahi_strerror(avahi_client_errno(c)) << "\n"; avahi_simple_poll_quit(simple_poll); } } diff --git a/client/browseZeroConf/browseBonjour.cpp b/client/browseZeroConf/browseBonjour.cpp index ed1d7ad6..a4551ced 100755 --- a/client/browseZeroConf/browseBonjour.cpp +++ b/client/browseZeroConf/browseBonjour.cpp @@ -260,7 +260,7 @@ bool BrowseBonjour::browse(const string& serviceName, mDNSResult& result, int ti return false; if (resultCollection.size() != 1) - logO << "Multiple servers found. Using first" << endl; + LOG(NOTICE) << "Multiple servers found. Using first" << endl; result = resultCollection[0]; diff --git a/client/clientConnection.cpp b/client/clientConnection.cpp index 8354f8ad..37409432 100644 --- a/client/clientConnection.cpp +++ b/client/clientConnection.cpp @@ -62,7 +62,7 @@ std::string ClientConnection::getMacAddress() const std::string mac = ::getMacAddress(socket_->native_handle()); if (mac.empty()) mac = "00:00:00:00:00:00"; - logO << "My MAC: \"" << mac << "\", socket: " << socket_->native_handle() << "\n"; + LOG(INFO) << "My MAC: \"" << mac << "\", socket: " << socket_->native_handle() << "\n"; return mac; } @@ -72,7 +72,7 @@ void ClientConnection::start() tcp::resolver resolver(io_service_); tcp::resolver::query query(tcp::v4(), host_, cpt::to_string(port_), asio::ip::resolver_query_base::numeric_service); auto iterator = resolver.resolve(query); - logO << "Connecting\n"; + LOG(DEBUG) << "Connecting\n"; socket_.reset(new tcp::socket(io_service_)); // struct timeval tv; // tv.tv_sec = 5; @@ -82,7 +82,7 @@ void ClientConnection::start() // setsockopt(socket->native_handle(), SOL_SOCKET, SO_SNDTIMEO, &tv, sizeof(tv)); socket_->connect(*iterator); connected_ = true; - logS(kLogNotice) << "Connected to " << socket_->remote_endpoint().address().to_string() << endl; + SLOG(LOG_NOTICE) << "Connected to " << socket_->remote_endpoint().address().to_string() << endl; active_ = true; readerThread_ = new thread(&ClientConnection::reader, this); } @@ -98,13 +98,13 @@ void ClientConnection::stop() if (socket_) { socket_->shutdown(asio::ip::tcp::socket::shutdown_both, ec); - if (ec) logE << "Error in socket shutdown: " << ec.message() << endl; + if (ec) LOG(ERROR) << "Error in socket shutdown: " << ec.message() << endl; socket_->close(ec); - if (ec) logE << "Error in socket close: " << ec.message() << endl; + if (ec) LOG(ERROR) << "Error in socket close: " << ec.message() << endl; } if (readerThread_) { - logD << "joining readerThread\n"; + LOG(DEBUG) << "joining readerThread\n"; readerThread_->join(); delete readerThread_; } @@ -114,18 +114,18 @@ void ClientConnection::stop() } readerThread_ = NULL; socket_.reset(); - logD << "readerThread terminated\n"; + LOG(DEBUG) << "readerThread terminated\n"; } bool ClientConnection::send(const msg::BaseMessage* message) const { // std::unique_lock mlock(mutex_); -//logD << "send: " << message->type << ", size: " << message->getSize() << "\n"; +//LOG(DEBUG) << "send: " << message->type << ", size: " << message->getSize() << "\n"; std::lock_guard socketLock(socketMutex_); if (!connected()) return false; -//logD << "send: " << message->type << ", size: " << message->getSize() << "\n"; +//LOG(DEBUG) << "send: " << message->type << ", size: " << message->getSize() << "\n"; asio::streambuf streambuf; std::ostream stream(&streambuf); tv t; @@ -142,7 +142,7 @@ shared_ptr ClientConnection::sendRequest(const msg::Base if (++reqId_ >= 10000) reqId_ = 1; message->id = reqId_; -// logO << "Req: " << message->id << "\n"; +// LOG(INFO) << "Req: " << message->id << "\n"; shared_ptr pendingRequest(new PendingRequest(reqId_)); std::unique_lock lock(pendingRequestsMutex_); @@ -152,12 +152,12 @@ shared_ptr ClientConnection::sendRequest(const msg::Base { response = pendingRequest->response; sumTimeout_ = chronos::msec(0); -// logO << "Resp: " << pendingRequest->id << "\n"; +// LOG(INFO) << "Resp: " << pendingRequest->id << "\n"; } else { sumTimeout_ += timeout; - logO << "timeout while waiting for response to: " << reqId_ << ", timeout " << sumTimeout_.count() << "\n"; + LOG(WARNING) << "timeout while waiting for response to: " << reqId_ << ", timeout " << sumTimeout_.count() << "\n"; if (sumTimeout_ > chronos::sec(10)) throw SnapException("sum timeout exceeded 10s"); } @@ -173,7 +173,7 @@ void ClientConnection::getNextMessage() vector buffer(baseMsgSize); socketRead(&buffer[0], baseMsgSize); baseMessage.deserialize(&buffer[0]); -// logD << "getNextMessage: " << baseMessage.type << ", size: " << baseMessage.size << ", id: " << baseMessage.id << ", refers: " << baseMessage.refersTo << "\n"; +// LOG(DEBUG) << "getNextMessage: " << baseMessage.type << ", size: " << baseMessage.size << ", id: " << baseMessage.id << ", refers: " << baseMessage.refersTo << "\n"; if (baseMessage.size > buffer.size()) buffer.resize(baseMessage.size); // { @@ -185,7 +185,7 @@ void ClientConnection::getNextMessage() { std::unique_lock lock(pendingRequestsMutex_); -// logD << "got lock - getNextMessage: " << baseMessage.type << ", size: " << baseMessage.size << ", id: " << baseMessage.id << ", refers: " << baseMessage.refersTo << "\n"; +// LOG(DEBUG) << "got lock - getNextMessage: " << baseMessage.type << ", size: " << baseMessage.size << ", id: " << baseMessage.id << ", refers: " << baseMessage.refersTo << "\n"; { for (auto req: pendingRequests_) { diff --git a/client/controller.cpp b/client/controller.cpp index e240aefb..be9171e6 100644 --- a/client/controller.cpp +++ b/client/controller.cpp @@ -50,7 +50,7 @@ Controller::Controller(const std::string& hostId, size_t instance) : MessageRece void Controller::onException(ClientConnection* connection, const std::exception& exception) { - logE << "Controller::onException: " << exception.what() << "\n"; + LOG(ERROR) << "Controller::onException: " << exception.what() << "\n"; exception_ = exception.what(); asyncException_ = true; } @@ -65,12 +65,12 @@ void Controller::onMessageReceived(ClientConnection* connection, const msg::Base { msg::PcmChunk* pcmChunk = new msg::PcmChunk(sampleFormat_, 0); pcmChunk->deserialize(baseMessage, buffer); -// logD << "chunk: " << pcmChunk->payloadSize << ", sampleFormat: " << sampleFormat_.rate << "\n"; +// LOG(DEBUG) << "chunk: " << pcmChunk->payloadSize << ", sampleFormat: " << sampleFormat_.rate << "\n"; if (decoder_->decode(pcmChunk)) { //TODO: do decoding in thread? stream_->addChunk(pcmChunk); - //logD << ", decoded: " << pcmChunk->payloadSize << ", Duration: " << pcmChunk->getDuration() << ", sec: " << pcmChunk->timestamp.sec << ", usec: " << pcmChunk->timestamp.usec/1000 << ", type: " << pcmChunk->type << "\n"; + //LOG(DEBUG) << ", decoded: " << pcmChunk->payloadSize << ", Duration: " << pcmChunk->getDuration() << ", sec: " << pcmChunk->timestamp.sec << ", usec: " << pcmChunk->timestamp.usec/1000 << ", type: " << pcmChunk->type << "\n"; } else delete pcmChunk; @@ -86,7 +86,7 @@ void Controller::onMessageReceived(ClientConnection* connection, const msg::Base { serverSettings_.reset(new msg::ServerSettings()); serverSettings_->deserialize(baseMessage, buffer); - logO << "ServerSettings - buffer: " << serverSettings_->getBufferMs() << ", latency: " << serverSettings_->getLatency() << ", volume: " << serverSettings_->getVolume() << ", muted: " << serverSettings_->isMuted() << "\n"; + LOG(INFO) << "ServerSettings - buffer: " << serverSettings_->getBufferMs() << ", latency: " << serverSettings_->getLatency() << ", volume: " << serverSettings_->getVolume() << ", muted: " << serverSettings_->isMuted() << "\n"; if (stream_ && player_) { player_->setVolume(serverSettings_->getVolume() / 100.); @@ -99,7 +99,7 @@ void Controller::onMessageReceived(ClientConnection* connection, const msg::Base headerChunk_.reset(new msg::CodecHeader()); headerChunk_->deserialize(baseMessage, buffer); - logO << "Codec: " << headerChunk_->codec << "\n"; + LOG(INFO) << "Codec: " << headerChunk_->codec << "\n"; decoder_.reset(nullptr); stream_ = nullptr; player_.reset(nullptr); @@ -116,7 +116,8 @@ void Controller::onMessageReceived(ClientConnection* connection, const msg::Base throw SnapException("codec not supported: \"" + headerChunk_->codec + "\""); sampleFormat_ = decoder_->setHeader(headerChunk_.get()); - logState << "sampleformat: " << sampleFormat_.rate << ":" << sampleFormat_.bits << ":" << sampleFormat_.channels << "\n"; + /// TODO: read in Android client + LOG(INFO) << TAG("state") << "sampleformat: " << sampleFormat_.rate << ":" << sampleFormat_.bits << ":" << sampleFormat_.channels << "\n"; stream_ = make_shared(sampleFormat_); stream_->setBufferLen(serverSettings_->getBufferMs() - latency_); @@ -137,7 +138,7 @@ void Controller::onMessageReceived(ClientConnection* connection, const msg::Base if (baseMessage.type != message_type::kTime) if (sendTimeSyncMessage(1000)) - logD << "time sync onMessageReceived\n"; + LOG(DEBUG) << "time sync onMessageReceived\n"; } @@ -166,7 +167,7 @@ void Controller::start(const PcmDevice& pcmDevice, const std::string& host, size void Controller::stop() { - logD << "Stopping Controller" << endl; + LOG(DEBUG) << "Stopping Controller" << endl; active_ = false; controllerThread_.join(); clientConnection_->stop(); @@ -202,7 +203,7 @@ void Controller::worker() chronos::usleep(100); } } - logO << "diff to server [ms]: " << (float)TimeProvider::getInstance().getDiffToServer().count() / 1000.f << "\n"; + LOG(INFO) << "diff to server [ms]: " << (float)TimeProvider::getInstance().getDiffToServer().count() / 1000.f << "\n"; /// Main loop while (active_) @@ -215,13 +216,13 @@ void Controller::worker() } if (sendTimeSyncMessage(5000)) - logO << "time sync main loop\n"; + LOG(DEBUG) << "time sync main loop\n"; } } catch (const std::exception& e) { asyncException_ = false; - logS(kLogErr) << "Exception in Controller::worker(): " << e.what() << endl; + SLOG(LOG_ERR) << "Exception in Controller::worker(): " << e.what() << endl; clientConnection_->stop(); player_.reset(); stream_.reset(); @@ -230,7 +231,7 @@ void Controller::worker() chronos::sleep(100); } } - logD << "Thread stopped\n"; + LOG(DEBUG) << "Thread stopped\n"; } diff --git a/client/decoder/flacDecoder.cpp b/client/decoder/flacDecoder.cpp index 1f3334d4..b2bca5d9 100644 --- a/client/decoder/flacDecoder.cpp +++ b/client/decoder/flacDecoder.cpp @@ -76,7 +76,7 @@ bool FlacDecoder::decode(msg::PcmChunk* chunk) if (lastError_) { - logE << "FLAC decode error: " << FLAC__StreamDecoderErrorStatusString[*lastError_] << "\n"; + LOG(ERROR) << "FLAC decode error: " << FLAC__StreamDecoderErrorStatusString[*lastError_] << "\n"; lastError_= nullptr; return false; } @@ -88,7 +88,7 @@ bool FlacDecoder::decode(msg::PcmChunk* chunk) int32_t s = (diffMs / 1000); int32_t us = (diffMs * 1000); us %= 1000000; - logD << "Cached: " << cacheInfo_.cachedBlocks_ << ", " << diffMs << "ms, " << s << "s, " << us << "us\n"; + LOG(DEBUG) << "Cached: " << cacheInfo_.cachedBlocks_ << ", " << diffMs << "ms, " << s << "s, " << us << "us\n"; chunk->timestamp = chunk->timestamp - tv(s, us); } return true; @@ -162,7 +162,7 @@ FLAC__StreamDecoderWriteStatus write_callback(const FLAC__StreamDecoder *decoder { if (buffer[channel] == NULL) { - logS(kLogErr) << "ERROR: buffer[" << channel << "] is NULL\n"; + SLOG(LOG_ERR) << "ERROR: buffer[" << channel << "] is NULL\n"; return FLAC__STREAM_DECODER_WRITE_STATUS_ABORT; } @@ -210,7 +210,7 @@ void metadata_callback(const FLAC__StreamDecoder *decoder, const FLAC__StreamMet void error_callback(const FLAC__StreamDecoder *decoder, FLAC__StreamDecoderErrorStatus status, void *client_data) { (void)decoder, (void)client_data; - logS(kLogErr) << "Got error callback: " << FLAC__StreamDecoderErrorStatusString[status] << "\n"; + SLOG(LOG_ERR) << "Got error callback: " << FLAC__StreamDecoderErrorStatusString[status] << "\n"; static_cast(client_data)->lastError_ = std::unique_ptr(new FLAC__StreamDecoderErrorStatus(status)); /// TODO, see issue #120: diff --git a/client/decoder/oggDecoder.cpp b/client/decoder/oggDecoder.cpp index 4ea9c13e..25500209 100644 --- a/client/decoder/oggDecoder.cpp +++ b/client/decoder/oggDecoder.cpp @@ -71,7 +71,7 @@ bool OggDecoder::decode(msg::PcmChunk* chunk) if (result < 0) { /* missing or corrupt data at this page position */ - logE << "Corrupt or missing data in bitstream; continuing...\n"; + LOG(ERROR) << "Corrupt or missing data in bitstream; continuing...\n"; continue; } @@ -229,11 +229,11 @@ SampleFormat OggDecoder::setHeader(msg::CodecHeader* chunk) std::string comment(*ptr); if (comment.find("SAMPLE_FORMAT=") == 0) sampleFormat_.setFormat(comment.substr(comment.find("=") + 1)); - logO << "comment: " << comment << "\n";; + LOG(INFO) << "comment: " << comment << "\n";; ++ptr; } - logO << "Encoded by: " << vc.vendor << "\n"; + LOG(INFO) << "Encoded by: " << vc.vendor << "\n"; return sampleFormat_; } diff --git a/client/player/alsaPlayer.cpp b/client/player/alsaPlayer.cpp index a77f7548..0fe10f5e 100644 --- a/client/player/alsaPlayer.cpp +++ b/client/player/alsaPlayer.cpp @@ -121,30 +121,30 @@ void AlsaPlayer::initAlsa() // long unsigned int periodsize = stream_->format.msRate() * 50;//2*rate/50; // if ((pcm = snd_pcm_hw_params_set_buffer_size_near(pcm_handle, params, &periodsize)) < 0) -// logE << "Unable to set buffer size " << (long int)periodsize << ": " << snd_strerror(pcm) << "\n"; +// LOG(ERROR) << "Unable to set buffer size " << (long int)periodsize << ": " << snd_strerror(pcm) << "\n"; /* Write parameters */ if ((pcm = snd_pcm_hw_params(handle_, params)) < 0) throw SnapException("Can't set harware parameters: " + string(snd_strerror(pcm))); /* Resume information */ - logD << "PCM name: " << snd_pcm_name(handle_) << "\n"; - logD << "PCM state: " << snd_pcm_state_name(snd_pcm_state(handle_)) << "\n"; + LOG(DEBUG) << "PCM name: " << snd_pcm_name(handle_) << "\n"; + LOG(DEBUG) << "PCM state: " << snd_pcm_state_name(snd_pcm_state(handle_)) << "\n"; snd_pcm_hw_params_get_channels(params, &tmp); - logD << "channels: " << tmp << "\n"; + LOG(DEBUG) << "channels: " << tmp << "\n"; snd_pcm_hw_params_get_rate(params, &tmp, 0); - logD << "rate: " << tmp << " bps\n"; + LOG(DEBUG) << "rate: " << tmp << " bps\n"; /* Allocate buffer to hold single period */ snd_pcm_hw_params_get_period_size(params, &frames_, 0); - logO << "frames: " << frames_ << "\n"; + LOG(INFO) << "frames: " << frames_ << "\n"; buff_size = frames_ * format.frameSize; //channels * 2 /* 2 -> sample size */; buff_ = (char *) malloc(buff_size); snd_pcm_hw_params_get_period_time(params, &tmp, NULL); - logD << "period time: " << tmp << "\n"; + LOG(DEBUG) << "period time: " << tmp << "\n"; snd_pcm_sw_params_t *swparams; snd_pcm_sw_params_alloca(&swparams); @@ -210,7 +210,7 @@ void AlsaPlayer::worker() } catch (const std::exception& e) { - logE << "Exception in initAlsa: " << e.what() << endl; + LOG(ERROR) << "Exception in initAlsa: " << e.what() << endl; chronos::sleep(100); } } @@ -218,7 +218,7 @@ void AlsaPlayer::worker() // snd_pcm_avail_delay(handle_, &framesAvail, &framesDelay); snd_pcm_delay(handle_, &framesDelay); chronos::usec delay((chronos::usec::rep) (1000 * (double) framesDelay / stream_->getFormat().msRate())); -// logO << "delay: " << framesDelay << ", delay[ms]: " << delay.count() / 1000 << "\n"; +// LOG(INFO) << "delay: " << framesDelay << ", delay[ms]: " << delay.count() / 1000 << "\n"; if (stream_->getPlayerChunk(buff_, delay, frames_)) { @@ -226,24 +226,24 @@ void AlsaPlayer::worker() adjustVolume(buff_, frames_); if ((pcm = snd_pcm_writei(handle_, buff_, frames_)) == -EPIPE) { - logE << "XRUN\n"; + LOG(ERROR) << "XRUN\n"; snd_pcm_prepare(handle_); } else if (pcm < 0) { - logE << "ERROR. Can't write to PCM device: " << snd_strerror(pcm) << "\n"; + LOG(ERROR) << "ERROR. Can't write to PCM device: " << snd_strerror(pcm) << "\n"; uninitAlsa(); } } else { - logO << "Failed to get chunk\n"; + LOG(INFO) << "Failed to get chunk\n"; while (active_ && !stream_->waitForChunk(100)) { - logD << "Waiting for chunk\n"; + LOG(DEBUG) << "Waiting for chunk\n"; if ((handle_ != NULL) && (chronos::getTickCount() - lastChunkTick > 5000)) { - logO << "No chunk received for 5000ms. Closing ALSA.\n"; + LOG(NOTICE) << "No chunk received for 5000ms. Closing ALSA.\n"; uninitAlsa(); stream_->clearChunks(); } diff --git a/client/player/coreAudioPlayer.cpp b/client/player/coreAudioPlayer.cpp index 6cd1cd8d..232b5818 100644 --- a/client/player/coreAudioPlayer.cpp +++ b/client/player/coreAudioPlayer.cpp @@ -54,7 +54,7 @@ void CoreAudioPlayer::playerCallback(AudioQueueRef queue, AudioQueueBufferRef bu size_t bufferedMs = bufferedFrames * 1000 / pubStream_->getFormat().rate + (ms_ * (NUM_BUFFERS - 1)); /// 15ms DAC delay. Based on trying. bufferedMs += 15; -// logO << "buffered: " << bufferedFrames << ", ms: " << bufferedMs << ", mSampleTime: " << timestamp.mSampleTime << "\n"; +// LOG(INFO) << "buffered: " << bufferedFrames << ", ms: " << bufferedMs << ", mSampleTime: " << timestamp.mSampleTime << "\n"; /// TODO: sometimes this bufferedMS or AudioTimeStamp wraps around 1s (i.e. we're 1s out of sync (behind)) and recovers later on chronos::usec delay(bufferedMs * 1000); @@ -63,11 +63,11 @@ void CoreAudioPlayer::playerCallback(AudioQueueRef queue, AudioQueueBufferRef bu { if (chronos::getTickCount() - lastChunkTick > 5000) { - logO << "No chunk received for 5000ms. Closing Audio Queue.\n"; + LOG(NOTICE) << "No chunk received for 5000ms. Closing Audio Queue.\n"; uninitAudioQueue(queue); return; } -// logO << "Failed to get chunk. Playing silence.\n"; +// LOG(INFO) << "Failed to get chunk. Playing silence.\n"; memset(buffer, 0, buff_size_); } else @@ -98,7 +98,7 @@ void CoreAudioPlayer::worker() } catch (const std::exception& e) { - logE << "Exception in worker: " << e.what() << "\n"; + LOG(ERROR) << "Exception in worker: " << e.what() << "\n"; chronos::sleep(100); } } @@ -135,7 +135,7 @@ void CoreAudioPlayer::initAudioQueue() frames_ = (sampleFormat.rate * ms_) / 1000; ms_ = frames_ * 1000 / sampleFormat.rate; buff_size_ = frames_ * sampleFormat.frameSize; - logO << "frames: " << frames_ << ", ms: " << ms_ << ", buffer size: " << buff_size_ << "\n"; + LOG(INFO) << "frames: " << frames_ << ", ms: " << ms_ << ", buffer size: " << buff_size_ << "\n"; AudioQueueBufferRef buffers[NUM_BUFFERS]; for (int i = 0; i < NUM_BUFFERS; i++) @@ -145,7 +145,7 @@ void CoreAudioPlayer::initAudioQueue() callback(this, queue, buffers[i]); } - logE << "CoreAudioPlayer::worker\n"; + LOG(ERROR) << "CoreAudioPlayer::worker\n"; AudioQueueCreateTimeline(queue, &timeLine_); AudioQueueStart(queue, NULL); CFRunLoopRun(); diff --git a/client/player/openslPlayer.cpp b/client/player/openslPlayer.cpp index 16abebb0..6055be49 100644 --- a/client/player/openslPlayer.cpp +++ b/client/player/openslPlayer.cpp @@ -71,7 +71,7 @@ void OpenslPlayer::playerCallback(SLAndroidSimpleBufferQueueItf bq) { if (bq != bqPlayerBufferQueue) { - logE << "Wrong bq!\n"; + LOG(ERROR) << "Wrong bq!\n"; return; } @@ -81,7 +81,7 @@ void OpenslPlayer::playerCallback(SLAndroidSimpleBufferQueueItf bq) if (lastTick != 0) { diff = now - lastTick; -// logE << "diff: " << diff << ", frames: " << player->frames_ / 44.1 << "\n"; +// LOG(ERROR) << "diff: " << diff << ", frames: " << player->frames_ / 44.1 << "\n"; // if (diff <= 50) // { // usleep(1000 * (50 - diff)); @@ -92,7 +92,7 @@ void OpenslPlayer::playerCallback(SLAndroidSimpleBufferQueueItf bq) */ // size_t d = player->frames_ / 0.48d; -// logE << "Delay: " << d << "\n"; +// LOG(ERROR) << "Delay: " << d << "\n"; // SLAndroidSimpleBufferQueueState state; // (*bq)->GetState(bq, &state); // cout << "bqPlayerCallback count: " << state.count << ", idx: " << state.index << "\n"; @@ -101,7 +101,7 @@ void OpenslPlayer::playerCallback(SLAndroidSimpleBufferQueueItf bq) // chronos::usec delay((250 - diff) * 1000); // while (active_ && !stream_->waitForChunk(100)) -// logO << "Waiting for chunk\n"; +// LOG(INFO) << "Waiting for chunk\n"; if (!active_) return; @@ -109,7 +109,7 @@ void OpenslPlayer::playerCallback(SLAndroidSimpleBufferQueueItf bq) chronos::usec delay(ms_ * 1000); if (!pubStream_->getPlayerChunk(buffer[curBuffer], delay, frames_)) { -// logO << "Failed to get chunk. Playing silence.\n"; +// LOG(INFO) << "Failed to get chunk. Playing silence.\n"; memset(buffer[curBuffer], 0, buff_size); } else @@ -196,7 +196,7 @@ void OpenslPlayer::initOpensl() frames_ = format.rate / (1000 / ms_);// * format.channels; // 1920; // 48000 * 2 / 50 // => 50ms buff_size = frames_ * format.frameSize /* 2 -> sample size */; - logO << "frames: " << frames_ << ", channels: " << format.channels << ", rate: " << format.rate << ", buff: " << buff_size << "\n"; + LOG(INFO) << "frames: " << frames_ << ", channels: " << format.channels << ", rate: " << format.rate << ", buff: " << buff_size << "\n"; SLresult result; // create engine @@ -347,17 +347,17 @@ void OpenslPlayer::uninitOpensl() // if (!active_) // return; - logO << "uninitOpensl\n"; + LOG(INFO) << "uninitOpensl\n"; SLresult result; - logO << "OpenSLWrap_Shutdown - stopping playback\n"; + LOG(INFO) << "OpenSLWrap_Shutdown - stopping playback\n"; if (bqPlayerPlay != NULL) { result = (*bqPlayerPlay)->SetPlayState(bqPlayerPlay, SL_PLAYSTATE_STOPPED); if (SL_RESULT_SUCCESS != result) - logE << "SetPlayState failed\n"; + LOG(ERROR) << "SetPlayState failed\n"; } - logO << "OpenSLWrap_Shutdown - deleting player object\n"; + LOG(INFO) << "OpenSLWrap_Shutdown - deleting player object\n"; if (bqPlayerObject != NULL) { @@ -368,7 +368,7 @@ void OpenslPlayer::uninitOpensl() bqPlayerVolume = NULL; } - logO << "OpenSLWrap_Shutdown - deleting mix object\n"; + LOG(INFO) << "OpenSLWrap_Shutdown - deleting mix object\n"; if (outputMixObject != NULL) { @@ -376,7 +376,7 @@ void OpenslPlayer::uninitOpensl() outputMixObject = NULL; } - logO << "OpenSLWrap_Shutdown - deleting engine object\n"; + LOG(INFO) << "OpenSLWrap_Shutdown - deleting engine object\n"; if (engineObject != NULL) { @@ -391,7 +391,7 @@ void OpenslPlayer::uninitOpensl() delete [] buffer[1]; buffer[1] = NULL; - logO << "OpenSLWrap_Shutdown - finished\n"; + LOG(INFO) << "OpenSLWrap_Shutdown - finished\n"; active_ = false; } diff --git a/client/player/player.cpp b/client/player/player.cpp index 274e1d07..24ef599f 100644 --- a/client/player/player.cpp +++ b/client/player/player.cpp @@ -89,7 +89,7 @@ void Player::setVolume(double volume) double base = M_E; // double base = 10.; volume_ = (pow(base, volume)-1) / (base-1); - logD << "setVolume: " << volume << " => " << volume_ << "\n"; + LOG(DEBUG) << "setVolume: " << volume << " => " << volume_ << "\n"; } diff --git a/client/snapClient.cpp b/client/snapClient.cpp index bad990da..d9513088 100644 --- a/client/snapClient.cpp +++ b/client/snapClient.cpp @@ -115,7 +115,7 @@ int main (int argc, char **argv) } catch (const std::invalid_argument& e) { - logS(kLogErr) << "Exception: " << e.what() << std::endl; + SLOG(LOG_ERR) << "Exception: " << e.what() << std::endl; cout << "\n" << op << "\n"; exit(EXIT_FAILURE); } @@ -153,7 +153,12 @@ int main (int argc, char **argv) if (instance <= 0) std::invalid_argument("instance id must be >= 1"); - std::clog.rdbuf(new Log("snapclient", LOG_DAEMON)); + Log::init( + { + make_shared(LogPriority::info, LogSink::Type::all), //, "%Y-%m-%d %H-%M-%S [#prio]"), + make_shared("snapclient", LogPriority::debug, LogSink::Type::special) + } + ); signal(SIGHUP, signal_handler); signal(SIGTERM, signal_handler); @@ -187,7 +192,7 @@ int main (int argc, char **argv) processPriority = 19; if (processPriority != 0) setpriority(PRIO_PROCESS, 0, processPriority); - logS(kLogNotice) << "daemon started" << std::endl; + SLOG(LOG_NOTICE) << "daemon started" << std::endl; } #endif @@ -213,13 +218,13 @@ int main (int argc, char **argv) { host = avahiResult.ip_; port = avahiResult.port_; - logO << "Found server " << host << ":" << port << "\n"; + LOG(INFO) << "Found server " << host << ":" << port << "\n"; break; } } catch (const std::exception& e) { - logS(kLogErr) << "Exception: " << e.what() << std::endl; + SLOG(LOG_ERR) << "Exception: " << e.what() << std::endl; } chronos::sleep(500); } @@ -229,7 +234,7 @@ int main (int argc, char **argv) std::unique_ptr controller(new Controller(hostIdValue.getValue(), instance)); if (!g_terminated) { - logO << "Latency: " << latency << "\n"; + LOG(INFO) << "Latency: " << latency << "\n"; controller->start(pcmDevice, host, port, latency); while(!g_terminated) chronos::sleep(100); @@ -238,11 +243,11 @@ int main (int argc, char **argv) } catch (const std::exception& e) { - logS(kLogErr) << "Exception: " << e.what() << std::endl; + SLOG(LOG_ERR) << "Exception: " << e.what() << std::endl; exitcode = EXIT_FAILURE; } - logS(kLogNotice) << "daemon terminated." << endl; + SLOG(LOG_NOTICE) << "daemon terminated." << endl; exit(exitcode); } diff --git a/client/stream.cpp b/client/stream.cpp index 791a99cf..622d3176 100644 --- a/client/stream.cpp +++ b/client/stream.cpp @@ -52,7 +52,7 @@ void Stream::setRealSampleRate(double sampleRate) correctAfterXFrames_ = 0; else correctAfterXFrames_ = round((format_.rate / sampleRate) / (format_.rate / sampleRate - 1.)); -// logD << "Correct after X: " << correctAfterXFrames_ << " (Real rate: " << sampleRate << ", rate: " << format_.rate << ")\n"; +// LOG(DEBUG) << "Correct after X: " << correctAfterXFrames_ << " (Real rate: " << sampleRate << ", rate: " << format_.rate << ")\n"; } @@ -76,7 +76,7 @@ void Stream::addChunk(msg::PcmChunk* chunk) while (chunks_.size() * chunk->duration().count() > 10000) chunks_.pop(); chunks_.push(shared_ptr(chunk)); -// logD << "new chunk: " << chunk->duration().count() << ", Chunks: " << chunks_.size() << "\n"; +// LOG(DEBUG) << "new chunk: " << chunk->duration().count() << ", Chunks: " << chunks_.size() << "\n"; } @@ -106,8 +106,8 @@ time_point_ms Stream::seekTo(const time_point_ms& to) while (to > chunk_->timePoint())// + std::chrono::milliseconds((long int)chunk_->getDuration()))// { chunk_ = chunks_.pop(); - logD << "\nto: " << Chunk::getAge(to) << "\t chunk: " << Chunk::getAge(chunk_->timePoint()) << "\n"; - logD << "diff: " << std::chrono::duration_cast((to - chunk_->timePoint())).count() << "\n"; + LOG(DEBUG) << "\nto: " << Chunk::getAge(to) << "\t chunk: " << Chunk::getAge(chunk_->timePoint()) << "\n"; + LOG(DEBUG) << "diff: " << std::chrono::duration_cast((to - chunk_->timePoint())).count() << "\n"; } chunk_->seek(std::chrono::duration_cast(to - chunk_->timePoint()).count() * format_.msRate()); return chunk_->timePoint(); @@ -164,7 +164,7 @@ cs::time_point_clk Stream::getNextPlayerChunk(void* outputBuffer, const cs::usec float factor = (float)toRead / framesPerBuffer;//(float)(framesPerBuffer*channels_); // if (abs(framesCorrection) > 1) -// logO << "correction: " << framesCorrection << ", factor: " << factor << "\n"; +// LOG(INFO) << "correction: " << framesCorrection << ", factor: " << factor << "\n"; float idx = 0; for (size_t n=0; n bufferMs_) { - logO << "outputBufferDacTime > bufferMs: " << cs::duration(outputBufferDacTime) << " > " << cs::duration(bufferMs_) << "\n"; + LOG(INFO) << "outputBufferDacTime > bufferMs: " << cs::duration(outputBufferDacTime) << " > " << cs::duration(bufferMs_) << "\n"; sleep_ = cs::usec(0); return false; } if (!chunk_ && !chunks_.try_pop(chunk_, outputBufferDacTime)) { - //logO << "no chunks available\n"; + //LOG(INFO) << "no chunks available\n"; sleep_ = cs::usec(0); return false; } @@ -220,19 +220,19 @@ bool Stream::getPlayerChunk(void* outputBuffer, const cs::usec& outputBufferDacT /// age < 0 => play in -age /// age > 0 => too old cs::usec age = std::chrono::duration_cast(TimeProvider::serverNow() - chunk_->start()) - bufferMs_ + outputBufferDacTime; -// logO << "age: " << age.count() / 1000 << "\n"; +// LOG(INFO) << "age: " << age.count() / 1000 << "\n"; if ((sleep_.count() == 0) && (cs::abs(age) > cs::msec(200))) { - logO << "age > 200: " << cs::duration(age) << "\n"; + LOG(INFO) << "age > 200: " << cs::duration(age) << "\n"; sleep_ = age; } try { - //logD << "framesPerBuffer: " << framesPerBuffer << "\tms: " << framesPerBuffer*2 / PLAYER_CHUNK_MS_SIZE << "\t" << PLAYER_CHUNK_SIZE << "\n"; + //LOG(DEBUG) << "framesPerBuffer: " << framesPerBuffer << "\tms: " << framesPerBuffer*2 / PLAYER_CHUNK_MS_SIZE << "\t" << PLAYER_CHUNK_SIZE << "\n"; cs::nsec bufferDuration = cs::nsec(cs::nsec::rep(framesPerBuffer / format_.nsRate())); -// logD << "buffer duration: " << bufferDuration.count() << "\n"; +// LOG(DEBUG) << "buffer duration: " << bufferDuration.count() << "\n"; cs::usec correction = cs::usec(0); if (sleep_.count() != 0) @@ -240,24 +240,24 @@ bool Stream::getPlayerChunk(void* outputBuffer, const cs::usec& outputBufferDacT resetBuffers(); if (sleep_ < -bufferDuration/2) { - logO << "sleep < -bufferDuration/2: " << cs::duration(sleep_) << " < " << -cs::duration(bufferDuration)/2 << ", "; + LOG(INFO) << "sleep < -bufferDuration/2: " << cs::duration(sleep_) << " < " << -cs::duration(bufferDuration)/2 << ", "; // We're early: not enough chunks_. play silence. Reference chunk_ is the oldest (front) one sleep_ = chrono::duration_cast(TimeProvider::serverNow() - getSilentPlayerChunk(outputBuffer, framesPerBuffer) - bufferMs_ + outputBufferDacTime); - logO << "sleep: " << cs::duration(sleep_) << "\n"; + LOG(INFO) << "sleep: " << cs::duration(sleep_) << "\n"; if (sleep_ < -bufferDuration/2) return true; } else if (sleep_ > bufferDuration/2) { - logO << "sleep > bufferDuration/2: " << cs::duration(sleep_) << " > " << cs::duration(bufferDuration)/2 << "\n"; + LOG(INFO) << "sleep > bufferDuration/2: " << cs::duration(sleep_) << " > " << cs::duration(bufferDuration)/2 << "\n"; // We're late: discard oldest chunks while (sleep_ > chunk_->duration()) { - logO << "sleep > chunkDuration: " << cs::duration(sleep_) << " > " << chunk_->duration().count() << ", chunks: " << chunks_.size() << ", out: " << cs::duration(outputBufferDacTime) << ", needed: " << cs::duration(bufferDuration) << "\n"; + LOG(INFO) << "sleep > chunkDuration: " << cs::duration(sleep_) << " > " << chunk_->duration().count() << ", chunks: " << chunks_.size() << ", out: " << cs::duration(outputBufferDacTime) << ", needed: " << cs::duration(bufferDuration) << "\n"; sleep_ = std::chrono::duration_cast(TimeProvider::serverNow() - chunk_->start() - bufferMs_ + outputBufferDacTime); if (!chunks_.try_pop(chunk_, outputBufferDacTime)) { - logO << "no chunks available\n"; + LOG(INFO) << "no chunks available\n"; chunk_ = NULL; sleep_ = cs::usec(0); return false; @@ -278,7 +278,7 @@ bool Stream::getPlayerChunk(void* outputBuffer, const cs::usec& outputBufferDacT } else { - logO << "Sleep " << cs::duration(sleep_) << "\n"; + LOG(INFO) << "Sleep " << cs::duration(sleep_) << "\n"; correction = sleep_; sleep_ = cs::usec(0); } @@ -303,7 +303,7 @@ bool Stream::getPlayerChunk(void* outputBuffer, const cs::usec& outputBufferDacT { if (cs::usec(abs(median_)) > cs::msec(1)) { - logO << "pBuffer->full() && (abs(median_) > 1): " << median_ << "\n"; + LOG(INFO) << "pBuffer->full() && (abs(median_) > 1): " << median_ << "\n"; sleep_ = cs::usec(median_); } /* else if (cs::usec(median_) > cs::usec(300)) @@ -319,7 +319,7 @@ bool Stream::getPlayerChunk(void* outputBuffer, const cs::usec& outputBufferDacT { if (cs::usec(abs(shortMedian_)) > cs::msec(5)) { - logO << "pShortBuffer->full() && (abs(shortMedian_) > 5): " << shortMedian_ << "\n"; + LOG(INFO) << "pShortBuffer->full() && (abs(shortMedian_) > 5): " << shortMedian_ << "\n"; sleep_ = cs::usec(shortMedian_); } /* else @@ -329,7 +329,7 @@ bool Stream::getPlayerChunk(void* outputBuffer, const cs::usec& outputBufferDacT */ } else if (miniBuffer_.full() && (cs::usec(abs(miniBuffer_.median())) > cs::msec(50))) { - logO << "pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): " << miniBuffer_.median() << "\n"; + LOG(INFO) << "pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): " << miniBuffer_.median() << "\n"; sleep_ = cs::usec((cs::msec::rep)miniBuffer_.mean()); } } @@ -341,7 +341,7 @@ bool Stream::getPlayerChunk(void* outputBuffer, const cs::usec& outputBufferDacT if (lastAge != msAge) { lastAge = msAge; - logO << "Sleep " << cs::duration(sleep_) << ", age: " << msAge << ", bufferDuration: " << cs::duration(bufferDuration) << "\n"; + LOG(INFO) << "Sleep " << cs::duration(sleep_) << ", age: " << msAge << ", bufferDuration: " << cs::duration(bufferDuration) << "\n"; } } else if (shortBuffer_.full()) @@ -361,8 +361,8 @@ bool Stream::getPlayerChunk(void* outputBuffer, const cs::usec& outputBufferDacT lastUpdate_ = now; median_ = buffer_.median(); shortMedian_ = shortBuffer_.median(); - logO << "Chunk: " << age.count()/100 << "\t" << miniBuffer_.median()/100 << "\t" << shortMedian_/100 << "\t" << median_/100 << "\t" << buffer_.size() << "\t" << cs::duration(outputBufferDacTime) << "\n"; -// logO << "Chunk: " << age.count()/1000 << "\t" << miniBuffer_.median()/1000 << "\t" << shortMedian_/1000 << "\t" << median_/1000 << "\t" << buffer_.size() << "\t" << cs::duration(outputBufferDacTime) << "\n"; + LOG(INFO) << "Chunk: " << age.count()/100 << "\t" << miniBuffer_.median()/100 << "\t" << shortMedian_/100 << "\t" << median_/100 << "\t" << buffer_.size() << "\t" << cs::duration(outputBufferDacTime) << "\n"; +// LOG(INFO) << "Chunk: " << age.count()/1000 << "\t" << miniBuffer_.median()/1000 << "\t" << shortMedian_/1000 << "\t" << median_/1000 << "\t" << buffer_.size() << "\t" << cs::duration(outputBufferDacTime) << "\n"; } return (abs(cs::duration(age)) < 500); } diff --git a/client/timeProvider.cpp b/client/timeProvider.cpp index b7ca17a7..e9c9a466 100644 --- a/client/timeProvider.cpp +++ b/client/timeProvider.cpp @@ -43,7 +43,7 @@ void TimeProvider::setDiffToServer(double ms) /// clear diffBuffer if last update is older than a minute if (!diffBuffer_.empty() && (std::abs(now.tv_sec - lastTimeSync) > 60)) { - logO << "Last time sync older than a minute. Clearing time buffer\n"; + LOG(INFO) << "Last time sync older than a minute. Clearing time buffer\n"; diffToServer_ = ms*1000; diffBuffer_.clear(); } @@ -51,7 +51,7 @@ void TimeProvider::setDiffToServer(double ms) diffBuffer_.add(ms*1000); diffToServer_ = diffBuffer_.median(3); -// logO << "setDiffToServer: " << ms << ", diff: " << diffToServer_ / 1000.f << "\n"; +// LOG(INFO) << "setDiffToServer: " << ms << ", diff: " << diffToServer_ / 1000.f << "\n"; } /* diff --git a/common/log.cpp b/common/log.cpp deleted file mode 100644 index 6c69a53a..00000000 --- a/common/log.cpp +++ /dev/null @@ -1,132 +0,0 @@ -/*** - This file is part of snapcast - Copyright (C) 2014-2017 Johannes Pohl - - 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 3 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, see . -***/ - -#include "log.h" -#include -#include -#include -#include - - -Log::Log(std::string ident, int facility) -{ - facility_ = facility; - priority_ = kLogDebug; - strncpy(ident_, ident.c_str(), sizeof(ident_)); - ident_[sizeof(ident_)-1] = '\0'; - - openlog(ident_, LOG_PID, facility_); -} - - -std::string Log::Timestamp() const -{ - struct tm * dt; - char buffer [30]; - std::time_t t = std::time(nullptr); - dt = localtime(&t); - strftime(buffer, sizeof(buffer), "%Y-%m-%d %H-%M-%S", dt); - return std::string(buffer); -} - - -std::string Log::toString(LogPriority logPriority) const -{ - switch (logPriority) - { - case kDbg: - return "dbg"; - case kOut: - return "out"; - case kState: - return "state"; - case kErr: - return "err"; - - case kLogEmerg: - return "Emerg"; - case kLogAlert: - return "Alert"; - case kLogCrit: - return "Crit"; - case kLogErr: - return "Err"; - case kLogWarning: - return "Warning"; - case kLogNotice: - return "Notice"; - case kLogInfo: - return "Info"; - case kLogDebug: - return "Debug"; - default: - std::stringstream ss; - ss << logPriority; - return ss.str(); - } -} - - -int Log::sync() -{ - if (buffer_.str().length()) - { - if (priority_ == kDbg) -#ifdef DEBUG_LOG - std::cout << Timestamp() << " [dbg] " << buffer_.str() << std::flush; -#else - ; -#endif - else if ((priority_ == kOut) || (priority_ == kState) || (priority_ == kErr)) - std::cout << Timestamp() << " [" << toString(priority_) << "] " << buffer_.str() << std::flush; - else - { - std::cout << Timestamp() << " [" << toString(priority_) << "] " << buffer_.str() << std::flush; - syslog(priority_, "%s", buffer_.str().c_str()); - } - buffer_.str(""); - buffer_.clear(); - priority_ = kLogDebug; // default to debug for each message - } - return 0; -} - - -int Log::overflow(int c) -{ - if (c != EOF) - { - buffer_ << static_cast(c); - if (c == '\n') - sync(); - } - else - { - sync(); - } - return c; -} - - -std::ostream& operator<< (std::ostream& os, const LogPriority& log_priority) -{ - static_cast(os.rdbuf())->priority_ = log_priority; - return os; -} - - diff --git a/common/log.h b/common/log.h index ead70632..50dd270c 100644 --- a/common/log.h +++ b/common/log.h @@ -1,6 +1,13 @@ /*** - This file is part of snapcast - Copyright (C) 2014-2017 Johannes Pohl + __ __ _ _ __ __ ___ + / _\ ( )( \/ )( ) / \ / __) + / \ )( ) ( / (_/\( O )( (_ \ + \_/\_/(__)(_/\_)\____/ \__/ \___/ + version 0.6.0 + https://github.com/badaix/aixlog + + This file is part of aixlog + Copyright (C) 2017 Johannes Pohl 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 @@ -16,57 +23,749 @@ along with this program. If not, see . ***/ +/// inspired by "eater": +/// https://stackoverflow.com/questions/2638654/redirect-c-stdclog-to-syslog-on-unix -#ifndef LOG_H -#define LOG_H +/// TODO: add global log level -#include + +#ifndef AIX_LOG_HPP +#define AIX_LOG_HPP + +#include +#include +#include +#include #include -#include +#include #include +#include +#ifdef __ANDROID__ +#include +#endif +#ifdef __APPLE__ +#include +#endif +#ifdef _WIN32 +#include +#else +#include +#endif -#define logD std::clog << kDbg -#define logO std::clog << kOut -#define logE std::clog << kErr -#define logState std::clog << kState -#define logS(P) std::clog << P -//#define log logO -enum LogPriority +/// Internal helper defines +#define LOG_WO_TAG(P) std::clog << (LogPriority)P << Tag(__func__) << LogType::normal +#define SLOG_WO_TAG(P) std::clog << (LogPriority)P << Tag(__func__) << LogType::special + +#define LOG_TAG(P, T) std::clog << (LogPriority)P << Tag(T) << LogType::normal +#define SLOG_TAG(P, T) std::clog << (LogPriority)P << Tag(T) << LogType::special + +#define LOG_X(x,P,T,FUNC, ...) FUNC +#define SLOG_X(x,P,T,FUNC, ...) FUNC + + +/// External logger defines +#define LOG(...) LOG_X(,##__VA_ARGS__, LOG_TAG(__VA_ARGS__), LOG_WO_TAG(__VA_ARGS__)) +#define SLOG(...) SLOG_X(,##__VA_ARGS__, SLOG_TAG(__VA_ARGS__), SLOG_WO_TAG(__VA_ARGS__)) + +#define FUNC __func__ +#define TAG Tag +#define COND Conditional + + +enum class LogType { - kLogEmerg = LOG_EMERG, // system is unusable - kLogAlert = LOG_ALERT, // action must be taken immediately - kLogCrit = LOG_CRIT, // critical conditions - kLogErr = LOG_ERR, // error conditions - kLogWarning = LOG_WARNING, // warning conditions - kLogNotice = LOG_NOTICE, // normal, but significant, condition - kLogInfo = LOG_INFO, // informational message - kLogDebug = LOG_DEBUG, // debug-level message - kDbg, kOut, kState, kErr + normal, + special }; -std::ostream& operator<< (std::ostream& os, const LogPriority& log_priority); + +enum Priority +{ + EMERG = 0, // 0 system is unusable + ALERT = 1, // 1 action must be taken immediately + CRIT = 2, // 2 critical conditions + ERROR = 3, // 3 error conditions + WARNING = 4, // 4 warning conditions + NOTICE = 5, // 5 normal, but significant, condition + INFO = 6, // 6 informational message + DEBUG = 7 // 7 debug-level message +}; + + +enum class LogPriority : std::int8_t +{ + emerg = EMERG, + alert = ALERT, + critical= CRIT, + error = ERROR, + warning = WARNING, + notice = NOTICE, + info = INFO, + debug = DEBUG +}; + + + +enum class Color +{ + none = 0, + black = 1, + red = 2, + green = 3, + yellow = 4, + blue = 5, + magenta = 6, + cyan = 7, + white = 8 +}; + + + +struct LogColor +{ + LogColor(Color foreground = Color::none, Color background = Color::none) : + foreground(foreground), + background(background) + { + } + + Color foreground; + Color background; +}; + + + +struct Conditional +{ + Conditional() : Conditional(true) + { + } + + Conditional(bool value) : is_true_(value) + { + } + + void set(bool value) + { + is_true_ = value; + } + + bool is_true() const + { + return is_true_; + } + +private: + bool is_true_; +}; + + + +struct Tag +{ + Tag(std::nullptr_t) : tag(""), is_null(true) + { + } + + Tag() : Tag(nullptr) + { + } + + Tag(const std::string& tag) : tag(tag), is_null(false) + { + } + + virtual explicit operator bool() const + { + return !is_null; + } + + std::string tag; + +private: + bool is_null; +}; + + +typedef std::chrono::time_point time_point_sys_clock; + +struct LogSink +{ + enum class Type + { + normal, + special, + all + }; + + LogSink(LogPriority priority, Type type) : priority(priority), sink_type_(type) + { + } + + virtual ~LogSink() + { + } + + virtual void log(const time_point_sys_clock& timestamp, LogPriority priority, LogType type, const Tag& tag, const std::string& message) const = 0; + virtual Type get_type() const + { + return sink_type_; + } + + virtual LogSink& set_type(Type sink_type) + { + sink_type_ = sink_type; + return *this; + } + + LogPriority priority; + +protected: + Type sink_type_; +}; + + + +static std::ostream& operator<< (std::ostream& os, const LogPriority& log_priority); +static std::ostream& operator<< (std::ostream& os, const LogType& log_type); +static std::ostream& operator<< (std::ostream& os, const Tag& tag); +static std::ostream& operator<< (std::ostream& os, const Conditional& conditional); + +typedef std::shared_ptr log_sink_ptr; + class Log : public std::basic_streambuf > { public: - explicit Log(std::string ident, int facility); + static Log& instance() + { + static Log instance_; + return instance_; + } + + /// Without "init" every LOG(X) will simply go to clog + static void init(const std::vector log_sinks = {}) + { + for (auto sink: log_sinks) + Log::instance().add_logsink(sink); + + std::clog.rdbuf(&Log::instance()); + } + + void add_logsink(log_sink_ptr sink) + { + logSinks.push_back(sink); + } + + void remove_logsink(log_sink_ptr sink) + { + logSinks.erase(std::remove(logSinks.begin(), logSinks.end(), sink), logSinks.end()); + } + + static std::string toString(LogPriority logPriority) + { + switch (logPriority) + { + case LogPriority::emerg: + return "Emerg"; + case LogPriority::alert: + return "Alert"; + case LogPriority::critical: + return "Crit"; + case LogPriority::error: + return "Err"; + case LogPriority::warning: + return "Warn"; + case LogPriority::notice: + return "Notice"; + case LogPriority::info: + return "Info"; + case LogPriority::debug: + return "Debug"; + default: + std::stringstream ss; + ss << logPriority; + return ss.str(); + } + } + protected: - int sync(); - int overflow(int c); + Log() : type_(LogType::normal) + { + } + + int sync() + { + if (!buffer_.str().empty()) + { + auto now = std::chrono::system_clock::now(); + if (conditional_.is_true()) + { + for (const auto sink: logSinks) + { + if ( + (sink->get_type() == LogSink::Type::all) || + ((type_ == LogType::special) && (sink->get_type() == LogSink::Type::special)) || + ((type_ == LogType::normal) && (sink->get_type() == LogSink::Type::normal)) + ) + if (priority_ <= sink->priority) + sink->log(now, priority_, type_, tag_, buffer_.str()); + } + } + buffer_.str(""); + buffer_.clear(); + //priority_ = debug; // default to debug for each message + //type_ = kNormal; + tag_ = nullptr; + conditional_.set(true); + } + return 0; + } + + int overflow(int c) + { +/* if ( + (priority_ > loglevel_) && + ((type_ == kNormal) || !syslog_enabled_) // || (syslogpriority_ > loglevel_)) + ) + return c; +*/ if (c != EOF) + { + if (c == '\n') + sync(); + else + buffer_ << static_cast(c); + } + else + { + std::cout << "EOF\n"; + sync(); + } + return c; + } + private: friend std::ostream& operator<< (std::ostream& os, const LogPriority& log_priority); - std::string toString(LogPriority logPriority) const; - std::string Timestamp() const; + friend std::ostream& operator<< (std::ostream& os, const LogType& log_type); + friend std::ostream& operator<< (std::ostream& os, const Tag& tag); + friend std::ostream& operator<< (std::ostream& os, const Conditional& conditional); + std::stringstream buffer_; - int facility_; LogPriority priority_; - char ident_[50]; + LogType type_; + Tag tag_; + Conditional conditional_; + std::vector logSinks; }; + +struct LogSinkFormat : public LogSink +{ + LogSinkFormat(LogPriority priority, Type type, const std::string& format = "%Y-%m-%d %H-%M-%S [#prio] (#tag)") : // #logline") : + LogSink(priority, type), + format_(format) + { + } + + virtual void set_format(const std::string& format) + { + format_ = format; + } + + virtual void log(const time_point_sys_clock& timestamp, LogPriority priority, LogType type, const Tag& tag, const std::string& message) const = 0; + + +protected: + /// strftime format + proprietary "#ms" for milliseconds + virtual void do_log(std::ostream& stream, const time_point_sys_clock& timestamp, LogPriority priority, LogType type, const Tag& tag, const std::string& message) const + { + std::time_t now_c = std::chrono::system_clock::to_time_t(timestamp); + struct::tm now_tm = *std::localtime(&now_c); + + char buffer[256]; + strftime(buffer, sizeof buffer, format_.c_str(), &now_tm); + std::string result = buffer; + size_t pos = result.find("#ms"); + if (pos != std::string::npos) + { + int ms_part = std::chrono::time_point_cast(timestamp).time_since_epoch().count() % 1000; + char ms_str[4]; + sprintf(ms_str, "%03d", ms_part); + result.replace(pos, 3, ms_str); + } + + pos = result.find("#prio"); + if (pos != std::string::npos) + result.replace(pos, 5, Log::toString(priority)); + + + pos = result.find("#tag"); + if (pos != std::string::npos) + result.replace(pos, 4, tag?tag.tag:"log"); + + pos = result.find("#logline"); + if (pos != std::string::npos) + { + result.replace(pos, 8, message); + stream << result << std::endl; + } + else + { + if (result.empty() || (result.back() == ' ')) + stream << message << std::endl; + else + stream << result << " " << message << std::endl; + } + } + + std::string format_; +}; + + + +struct LogSinkCout : public LogSinkFormat +{ + LogSinkCout(LogPriority priority, Type type, const std::string& format = "%Y-%m-%d %H-%M-%S.#ms [#prio] (#tag)") : // #logline") : + LogSinkFormat(priority, type, format) + { + } + + virtual void log(const time_point_sys_clock& timestamp, LogPriority priority, LogType type, const Tag& tag, const std::string& message) const + { + if (priority <= this->priority) + do_log(std::cout, timestamp, priority, type, tag, message); + } +}; + + + +struct LogSinkCerr : public LogSinkFormat +{ + LogSinkCerr(LogPriority priority, Type type, const std::string& format = "%Y-%m-%d %H-%M-%S.#ms [#prio] (#tag)") : // #logline") : + LogSinkFormat(priority, type, format) + { + } + + virtual void log(const time_point_sys_clock& timestamp, LogPriority priority, LogType type, const Tag& tag, const std::string& message) const + { + if (priority <= this->priority) + do_log(std::cerr, timestamp, priority, type, tag, message); + } +}; + + + +/// Not tested due to unavailability of Windows +struct LogSinkOutputDebugString : LogSink +{ + LogSinkOutputDebugString(LogPriority priority, Type type = Type::all, const std::string& default_tag = "") : LogSink(priority, type) + { + } + + virtual void log(const time_point_sys_clock& timestamp, LogPriority priority, LogType type, const Tag& tag, const std::string& message) const + { +#ifdef _WIN32 + OutputDebugString(message.c_str()); +#endif + } +}; + + + +struct LogSinkUnifiedLogging : LogSink +{ + LogSinkUnifiedLogging(LogPriority priority, Type type = Type::all) : LogSink(priority, type) + { + } + +#ifdef __APPLE__ + os_log_type_t get_os_log_type(LogPriority priority) const + { + switch (priority) + { + case LogPriority::emerg: + case LogPriority::alert: + case LogPriority::critical: + return OS_LOG_TYPE_FAULT; + case LogPriority::error: + return OS_LOG_TYPE_ERROR; + case LogPriority::warning: + case LogPriority::notice: + return OS_LOG_TYPE_DEFAULT; + case LogPriority::info: + return OS_LOG_TYPE_INFO; + case LogPriority::debug: + return OS_LOG_TYPE_DEBUG; + default: + return OS_LOG_TYPE_DEFAULT; + } + } #endif + virtual void log(const time_point_sys_clock& timestamp, LogPriority priority, LogType type, const Tag& tag, const std::string& message) const + { +#ifdef __APPLE__ + os_log_with_type(OS_LOG_DEFAULT, get_os_log_type(priority), "%{public}s", message.c_str()); +#endif + } +}; + + + +struct LogSinkSyslog : public LogSink +{ + LogSinkSyslog(const char* ident, LogPriority priority, Type type) : LogSink(priority, type) + { +#ifndef _WIN32 + openlog(ident, LOG_PID, LOG_USER); +#endif + } + + virtual ~LogSinkSyslog() + { + closelog(); + } + + virtual void log(const time_point_sys_clock& timestamp, LogPriority priority, LogType type, const Tag& tag, const std::string& message) const + { +#ifndef _WIN32 + syslog((int)priority, "%s", message.c_str()); +#endif + } +}; + + + +struct LogSinkAndroid : public LogSink +{ + LogSinkAndroid(const std::string& ident, LogPriority priority, Type type = Type::all) : LogSink(priority, type), ident_(ident) + { + } + +#ifdef __ANDROID__ + android_LogPriority get_android_prio(LogPriority priority) const + { + switch (priority) + { + case LogPriority::emerg: + case LogPriority::alert: + case LogPriority::critical: + return ANDROID_LOG_FATAL; + case LogPriority::error: + return ANDROID_LOG_ERROR; + case LogPriority::warning: + return ANDROID_LOG_WARN; + case LogPriority::notice: + return ANDROID_LOG_DEFAULT; + case LogPriority::info: + return ANDROID_LOG_INFO; + case LogPriority::debug: + return ANDROID_LOG_DEBUG; + default: + return ANDROID_LOG_UNKNOWN; + } + } +#endif + + virtual void log(const time_point_sys_clock& timestamp, LogPriority priority, LogType type, const Tag& tag, const std::string& message) const + { +#ifdef __ANDROID__ + std::string log_tag;// = default_tag_; + if (tag) + { + if (!ident_.empty()) + log_tag = ident_ + "." + tag.tag; + else + log_tag = tag.tag; + } + else + log_tag = ident_; + + __android_log_write(get_android_prio(priority), log_tag.c_str(), message.c_str()); +#endif + } + +protected: + std::string ident_; +}; + + + +/// Not tested due to unavailability of Windows +struct LogSinkEventLog : public LogSink +{ + LogSinkEventLog(const std::string& ident, LogPriority priority, Type type = Type::all) : LogSink(priority, type) + { +#ifdef _WIN32 + event_log = RegisterEventSource(NULL, ident.c_str()); +#endif + } + +#ifdef _WIN32 + WORD get_type(LogPriority priority) const + { + switch (priority) + { + case LogPriority::emerg: + case LogPriority::alert: + case LogPriority::critical: + case LogPriority::error: + return EVENTLOG_ERROR_TYPE; + case LogPriority::warning: + return EVENTLOG_WARNING_TYPE; + case LogPriority::notice: + return EVENTLOG_SUCCESS; + case LogPriority::info: + case LogPriority::debug: + return EVENTLOG_INFORMATION_TYPE; + default: + return EVENTLOG_INFORMATION_TYPE; + } + } +#endif + + virtual void log(const time_point_sys_clock& timestamp, LogPriority priority, LogType type, const Tag& tag, const std::string& message) const + { +#ifdef _WIN32 + ReportEvent(event_log, get_type(priority), 0, 0, NULL, 1, 0, &message.c_str(), NULL); +#endif + } + +protected: +#ifdef _WIN32 + HANDLE event_log; +#endif +}; + + + +struct LogSinkNative : public LogSink +{ + LogSinkNative(const std::string& ident, LogPriority priority, Type type = Type::all) : + LogSink(priority, type), + log_sink_(nullptr), + ident_(ident) + { +#ifdef __ANDROID__ + log_sink_ = std::make_shared(ident_, priority, type); +#elif __APPLE__ + log_sink_ = std::make_shared(priority, type); +#elif _WIN32 + log_sink_ = std::make_shared(priority, type); +#else + log_sink_ = std::make_shared(ident_.c_str(), priority, type); +#endif + } + + virtual void log(const time_point_sys_clock& timestamp, LogPriority priority, LogType type, const Tag& tag, const std::string& message) const + { + if (log_sink_) + log_sink_->log(timestamp, priority, type, tag, message); + } + +protected: + log_sink_ptr log_sink_; + std::string ident_; +}; + + + +struct LogSinkCallback : public LogSink +{ + typedef std::function callback_fun; + + LogSinkCallback(LogPriority priority, Type type, callback_fun callback) : LogSink(priority, type), callback(callback) + { + } + + virtual void log(const time_point_sys_clock& timestamp, LogPriority priority, LogType type, const Tag& tag, const std::string& message) const + { + if (callback && (priority <= this->priority)) + callback(timestamp, priority, type, tag, message); + } + +private: + callback_fun callback; +}; + + + +static std::ostream& operator<< (std::ostream& os, const LogPriority& log_priority) +{ + Log* log = dynamic_cast(os.rdbuf()); + if (log && (log->priority_ != log_priority)) + { + log->sync(); + log->priority_ = log_priority; + } + return os; +} + + + +static std::ostream& operator<< (std::ostream& os, const LogType& log_type) +{ + Log* log = dynamic_cast(os.rdbuf()); + if (log) + log->type_ = log_type; + return os; +} + + + +static std::ostream& operator<< (std::ostream& os, const Tag& tag) +{ + Log* log = dynamic_cast(os.rdbuf()); + if (log) + log->tag_ = tag; + return os; +} + + + +static std::ostream& operator<< (std::ostream& os, const Conditional& conditional) +{ + Log* log = dynamic_cast(os.rdbuf()); + if (log) + log->conditional_.set(conditional.is_true()); + return os; +} + + + +static std::ostream& operator<< (std::ostream& os, const LogColor& log_color) +{ + os << "\033["; + if ((log_color.foreground == Color::none) && (log_color.background == Color::none)) + os << "0"; // reset colors if no params + + if (log_color.foreground != Color::none) + { + os << 29 + (int)log_color.foreground; + if (log_color.background != Color::none) + os << ";"; + } + if (log_color.background != Color::none) + os << 39 + (int)log_color.background; + os << "m"; + + return os; +} + + + +static std::ostream& operator<< (std::ostream& os, const Color& color) +{ + os << LogColor(color); + return os; +} + + + +#endif /// AIX_LOG_HPP + diff --git a/common/sampleFormat.cpp b/common/sampleFormat.cpp index e03e245c..a18d07ee 100644 --- a/common/sampleFormat.cpp +++ b/common/sampleFormat.cpp @@ -79,7 +79,7 @@ void SampleFormat::setFormat(uint32_t rate, uint16_t bits, uint16_t channels) if (bits == 24) sampleSize = 4; frameSize = channels*sampleSize; -// logD << "SampleFormat: " << rate << ":" << bits << ":" << channels << "\n"; +// LOG(DEBUG) << "SampleFormat: " << rate << ":" << bits << ":" << channels << "\n"; } diff --git a/server/Makefile b/server/Makefile index f10ab5b3..1d349138 100644 --- a/server/Makefile +++ b/server/Makefile @@ -31,7 +31,7 @@ endif CXXFLAGS += $(ADD_CFLAGS) -std=c++0x -Wall -Wno-unused-function -O3 -DASIO_STANDALONE -DVERSION=\"$(VERSION)\" -I. -I.. -isystem ../externals/asio/asio/include -I../externals/popl/include -I../externals/jsonrpcpp/lib -I../externals LDFLAGS = -lvorbis -lvorbisenc -logg -lFLAC -OBJ = snapServer.o config.o controlServer.o controlSession.o streamServer.o streamSession.o streamreader/streamUri.o streamreader/streamManager.o streamreader/pcmStream.o streamreader/pipeStream.o streamreader/fileStream.o streamreader/processStream.o streamreader/airplayStream.o streamreader/spotifyStream.o streamreader/watchdog.o encoder/encoderFactory.o encoder/flacEncoder.o encoder/pcmEncoder.o encoder/oggEncoder.o ../common/log.o ../common/sampleFormat.o ../message/pcmChunk.o ../externals/jsonrpcpp/lib/jsonrp.o +OBJ = snapServer.o config.o controlServer.o controlSession.o streamServer.o streamSession.o streamreader/streamUri.o streamreader/streamManager.o streamreader/pcmStream.o streamreader/pipeStream.o streamreader/fileStream.o streamreader/processStream.o streamreader/airplayStream.o streamreader/spotifyStream.o streamreader/watchdog.o encoder/encoderFactory.o encoder/flacEncoder.o encoder/pcmEncoder.o encoder/oggEncoder.o ../common/sampleFormat.o ../message/pcmChunk.o ../externals/jsonrpcpp/lib/jsonrp.o ifeq ($(ENDIAN), BIG) diff --git a/server/config.cpp b/server/config.cpp index e169c618..aed1129b 100644 --- a/server/config.cpp +++ b/server/config.cpp @@ -48,15 +48,15 @@ Config::Config() throw SnapException("failed to create settings directory: \"" + dir + "\": " + cpt::to_string(errno)); filename_ = dir + "server.json"; - logS(kLogNotice) << "Settings file: \"" << filename_ << "\"\n"; + SLOG(LOG_NOTICE) << "Settings file: \"" << filename_ << "\"\n"; int fd; if ((fd = open(filename_.c_str(), O_RDWR | O_CREAT, S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH)) == -1) { if (errno == EACCES) - throw std::runtime_error("failed to open file \"" + filename_ + "\", permission denied"); + throw std::runtime_error("failed to open file \"" + filename_ + "\", permission denied (error " + cpt::to_string(errno) + ")"); else - throw std::runtime_error("failed to open file \"" + filename_ + "\""); + throw std::runtime_error("failed to open file \"" + filename_ + "\", error " + cpt::to_string(errno)); } close(fd); @@ -83,7 +83,7 @@ Config::Config() } catch(const std::exception& e) { - logE << "Error reading config: " << e.what() << "\n"; + LOG(ERROR) << "Error reading config: " << e.what() << "\n"; } } diff --git a/server/controlServer.cpp b/server/controlServer.cpp index 1c1d22b5..328c77d2 100644 --- a/server/controlServer.cpp +++ b/server/controlServer.cpp @@ -48,7 +48,7 @@ void ControlServer::cleanup() { if (!(*it)->active()) { - logS(kLogErr) << "Session inactive. Removing\n"; + SLOG(LOG_ERR) << "Session inactive. Removing\n"; // don't block: remove ClientSession in a thread auto func = [](shared_ptr s)->void{s->stop();}; std::thread t(func, *it); @@ -76,7 +76,7 @@ void ControlServer::send(const std::string& message, const ControlSession* exclu void ControlServer::onMessageReceived(ControlSession* connection, const std::string& message) { std::lock_guard mlock(mutex_); - logD << "received: \"" << message << "\"\n"; + LOG(DEBUG) << "received: \"" << message << "\"\n"; if ((message == "quit") || (message == "exit") || (message == "bye")) { for (auto it = sessions_.begin(); it != sessions_.end(); ++it) @@ -115,7 +115,7 @@ void ControlServer::handleAccept(socket_ptr socket) setsockopt(socket->native_handle(), SOL_SOCKET, SO_RCVTIMEO, &tv, sizeof(tv)); setsockopt(socket->native_handle(), SOL_SOCKET, SO_SNDTIMEO, &tv, sizeof(tv)); // socket->set_option(boost::asio::ip::tcp::no_delay(false)); - logS(kLogNotice) << "ControlServer::NewConnection: " << socket->remote_endpoint().address().to_string() << endl; + SLOG(LOG_NOTICE) << "ControlServer::NewConnection: " << socket->remote_endpoint().address().to_string() << endl; shared_ptr session = make_shared(this, socket); { std::lock_guard mlock(mutex_); diff --git a/server/controlSession.cpp b/server/controlSession.cpp index e263725e..a6b3473f 100644 --- a/server/controlSession.cpp +++ b/server/controlSession.cpp @@ -52,7 +52,7 @@ void ControlSession::start() void ControlSession::stop() { - logD << "ControlSession::stop\n"; + LOG(DEBUG) << "ControlSession::stop\n"; std::lock_guard activeLock(activeMutex_); active_ = false; try @@ -62,18 +62,18 @@ void ControlSession::stop() { std::lock_guard socketLock(socketMutex_); socket_->shutdown(asio::ip::tcp::socket::shutdown_both, ec); - if (ec) logE << "Error in socket shutdown: " << ec.message() << "\n"; + if (ec) LOG(ERROR) << "Error in socket shutdown: " << ec.message() << "\n"; socket_->close(ec); - if (ec) logE << "Error in socket close: " << ec.message() << "\n"; + if (ec) LOG(ERROR) << "Error in socket close: " << ec.message() << "\n"; } if (readerThread_.joinable()) { - logD << "joining readerThread\n"; + LOG(DEBUG) << "joining readerThread\n"; readerThread_.join(); } if (writerThread_.joinable()) { - logD << "joining writerThread\n"; + LOG(DEBUG) << "joining writerThread\n"; messages_.abort_wait(); writerThread_.join(); } @@ -82,7 +82,7 @@ void ControlSession::stop() { } socket_ = NULL; - logD << "ControlSession stopped\n"; + LOG(DEBUG) << "ControlSession stopped\n"; } @@ -95,7 +95,7 @@ void ControlSession::sendAsync(const std::string& message) bool ControlSession::send(const std::string& message) const { - //logO << "send: " << message << ", size: " << message.length() << "\n"; + //LOG(INFO) << "send: " << message << ", size: " << message.length() << "\n"; std::lock_guard socketLock(socketMutex_); { std::lock_guard activeLock(activeMutex_); @@ -106,7 +106,7 @@ bool ControlSession::send(const std::string& message) const std::ostream request_stream(&streambuf); request_stream << message << "\r\n"; asio::write(*socket_.get(), streambuf); - //logO << "done\n"; + //LOG(INFO) << "done\n"; return true; } @@ -145,7 +145,7 @@ void ControlSession::reader() } catch (const std::exception& e) { - logS(kLogErr) << "Exception in ControlSession::reader(): " << e.what() << endl; + SLOG(LOG_ERR) << "Exception in ControlSession::reader(): " << e.what() << endl; } active_ = false; } @@ -166,7 +166,7 @@ void ControlSession::writer() } catch (const std::exception& e) { - logS(kLogErr) << "Exception in ControlSession::writer(): " << e.what() << endl; + SLOG(LOG_ERR) << "Exception in ControlSession::writer(): " << e.what() << endl; } active_ = false; } diff --git a/server/encoder/flacEncoder.cpp b/server/encoder/flacEncoder.cpp index 0a3822df..bfa67043 100644 --- a/server/encoder/flacEncoder.cpp +++ b/server/encoder/flacEncoder.cpp @@ -71,7 +71,7 @@ void FlacEncoder::encode(const msg::PcmChunk* chunk) { int samples = chunk->getSampleCount(); int frames = chunk->getFrameCount(); -// logO << "payload: " << chunk->payloadSize << "\tframes: " << frames << "\tsamples: " << samples << "\tduration: " << chunk->duration().count() << "\n"; +// LOG(INFO) << "payload: " << chunk->payloadSize << "\tframes: " << frames << "\tsamples: " << samples << "\tduration: " << chunk->duration().count() << "\n"; if (pcmBufferSize_ < samples) { @@ -104,7 +104,7 @@ void FlacEncoder::encode(const msg::PcmChunk* chunk) if (encodedSamples_ > 0) { double resMs = encodedSamples_ / ((double)sampleFormat_.rate / 1000.); -// logO << "encoded: " << chunk->payloadSize << "\tframes: " << encodedSamples_ << "\tres: " << resMs << "\n"; +// LOG(INFO) << "encoded: " << chunk->payloadSize << "\tframes: " << encodedSamples_ << "\tres: " << resMs << "\n"; encodedSamples_ = 0; listener_->onChunkEncoded(this, flacChunk_, resMs); flacChunk_ = new msg::PcmChunk(chunk->format, 0); @@ -118,7 +118,7 @@ FLAC__StreamEncoderWriteStatus FlacEncoder::write_callback(const FLAC__StreamEnc unsigned samples, unsigned current_frame) { -// logO << "write_callback: " << bytes << ", " << samples << ", " << current_frame << "\n"; +// LOG(INFO) << "write_callback: " << bytes << ", " << samples << ", " << current_frame << "\n"; if ((current_frame == 0) && (bytes > 0) && (samples == 0)) { headerChunk_->payload = (char*)realloc(headerChunk_->payload, headerChunk_->payloadSize + bytes); diff --git a/server/encoder/oggEncoder.cpp b/server/encoder/oggEncoder.cpp index 3aef4e89..352f63b6 100644 --- a/server/encoder/oggEncoder.cpp +++ b/server/encoder/oggEncoder.cpp @@ -55,7 +55,7 @@ std::string OggEncoder::name() const void OggEncoder::encode(const msg::PcmChunk* chunk) { double res = 0; - logD << "payload: " << chunk->payloadSize << "\tframes: " << chunk->getFrameCount() << "\tduration: " << chunk->duration().count() << "\n"; + LOG(DEBUG) << "payload: " << chunk->payloadSize << "\tframes: " << chunk->getFrameCount() << "\tduration: " << chunk->duration().count() << "\n"; int frames = chunk->getFrameCount(); float **buffer=vorbis_analysis_buffer(&vd_, frames); @@ -129,7 +129,7 @@ void OggEncoder::encode(const msg::PcmChunk* chunk) if (res > 0) { res /= (sampleFormat_.rate / 1000.); - // logO << "res: " << res << "\n"; + // LOG(INFO) << "res: " << res << "\n"; lastGranulepos_ = os_.granulepos; // make oggChunk smaller oggChunk->payload = (char*)realloc(oggChunk->payload, pos); @@ -249,7 +249,7 @@ void OggEncoder::initEncoder() break; headerChunk_->payloadSize += og_.header_len + og_.body_len; headerChunk_->payload = (char*)realloc(headerChunk_->payload, headerChunk_->payloadSize); - logD << "HeadLen: " << og_.header_len << ", bodyLen: " << og_.body_len << ", result: " << result << "\n"; + LOG(DEBUG) << "HeadLen: " << og_.header_len << ", bodyLen: " << og_.body_len << ", result: " << result << "\n"; memcpy(headerChunk_->payload + pos, og_.header, og_.header_len); pos += og_.header_len; memcpy(headerChunk_->payload + pos, og_.body, og_.body_len); diff --git a/server/publishZeroConf/publishAvahi.cpp b/server/publishZeroConf/publishAvahi.cpp index f6a75193..c4535abc 100644 --- a/server/publishZeroConf/publishAvahi.cpp +++ b/server/publishZeroConf/publishAvahi.cpp @@ -44,7 +44,7 @@ void PublishAvahi::publish(const std::vector& services) if (!(simple_poll = avahi_simple_poll_new())) { ///TODO: error handling - logE << "Failed to create simple poll object.\n"; + LOG(ERROR) << "Failed to create simple poll object.\n"; } /// Allocate a new client @@ -54,7 +54,7 @@ void PublishAvahi::publish(const std::vector& services) /// Check wether creating the client object succeeded if (!client_) { - logE << "Failed to create client: " << avahi_strerror(error) << "\n"; + LOG(ERROR) << "Failed to create client: " << avahi_strerror(error) << "\n"; } active_ = true; @@ -93,7 +93,7 @@ void PublishAvahi::entry_group_callback(AvahiEntryGroup *g, AvahiEntryGroupState { case AVAHI_ENTRY_GROUP_ESTABLISHED : /// The entry group has been established successfully - logO << "Service '" << name << "' successfully established.\n"; + LOG(INFO) << "Service '" << name << "' successfully established.\n"; break; case AVAHI_ENTRY_GROUP_COLLISION : @@ -105,7 +105,7 @@ void PublishAvahi::entry_group_callback(AvahiEntryGroup *g, AvahiEntryGroupState avahi_free(name); name = n; - logO << "Service name collision, renaming service to '" << name << "'\n"; + LOG(NOTICE) << "Service name collision, renaming service to '" << name << "'\n"; /// And recreate the services static_cast(userdata)->create_services(avahi_entry_group_get_client(g)); @@ -114,7 +114,7 @@ void PublishAvahi::entry_group_callback(AvahiEntryGroup *g, AvahiEntryGroupState case AVAHI_ENTRY_GROUP_FAILURE : - logE << "Entry group failure: " << avahi_strerror(avahi_client_errno(avahi_entry_group_get_client(g))) << "\n"; + LOG(ERROR) << "Entry group failure: " << avahi_strerror(avahi_client_errno(avahi_entry_group_get_client(g))) << "\n"; /// Some kind of failure happened while we were registering our services avahi_simple_poll_quit(simple_poll); @@ -136,7 +136,7 @@ void PublishAvahi::create_services(AvahiClient *c) { if (!(group = avahi_entry_group_new(c, entry_group_callback, this))) { - logE << "avahi_entry_group_new() failed: " << avahi_strerror(avahi_client_errno(c)) << "\n"; + LOG(ERROR) << "avahi_entry_group_new() failed: " << avahi_strerror(avahi_client_errno(c)) << "\n"; goto fail; } } @@ -145,7 +145,7 @@ void PublishAvahi::create_services(AvahiClient *c) int ret; if (avahi_entry_group_is_empty(group)) { - logO << "Adding service '" << name << "'\n"; + LOG(INFO) << "Adding service '" << name << "'\n"; /// We will now add two services and one subtype to the entry group for (const auto& service: services_) @@ -155,7 +155,7 @@ void PublishAvahi::create_services(AvahiClient *c) if (ret == AVAHI_ERR_COLLISION) goto collision; - logE << "Failed to add " << service.name_ << " service: " << avahi_strerror(ret) << "\n"; + LOG(ERROR) << "Failed to add " << service.name_ << " service: " << avahi_strerror(ret) << "\n"; goto fail; } } @@ -170,7 +170,7 @@ void PublishAvahi::create_services(AvahiClient *c) /// Tell the server to register the service if ((ret = avahi_entry_group_commit(group)) < 0) { - logE << "Failed to commit entry group: " << avahi_strerror(ret) << "\n"; + LOG(ERROR) << "Failed to commit entry group: " << avahi_strerror(ret) << "\n"; goto fail; } } @@ -184,7 +184,7 @@ collision: avahi_free(name); name = n; - logO << "Service name collision, renaming service to '" << name << "'\n"; + LOG(INFO) << "Service name collision, renaming service to '" << name << "'\n"; avahi_entry_group_reset(group); @@ -211,7 +211,7 @@ void PublishAvahi::client_callback(AvahiClient *c, AvahiClientState state, AVAHI case AVAHI_CLIENT_FAILURE: - logE << "Client failure: " << avahi_strerror(avahi_client_errno(c)) << "\n"; + LOG(ERROR) << "Client failure: " << avahi_strerror(avahi_client_errno(c)) << "\n"; avahi_simple_poll_quit(simple_poll); break; diff --git a/server/publishZeroConf/publishBonjour.cpp b/server/publishZeroConf/publishBonjour.cpp index 9e4f078a..abc2b5e0 100644 --- a/server/publishZeroConf/publishBonjour.cpp +++ b/server/publishZeroConf/publishBonjour.cpp @@ -90,7 +90,7 @@ void PublishBonjour::worker() DNSServiceErrorType err = DNSServiceProcessResult(clients[n]); if (err) { - logE << "DNSServiceProcessResult returned " << err << "\n"; + LOG(ERROR) << "DNSServiceProcessResult returned " << err << "\n"; active_ = false; } } @@ -100,7 +100,7 @@ void PublishBonjour::worker() // myTimerCallBack(); else if (result < 0) { - logE << "select() returned " << result << " errno " << errno << " " << strerror(errno) << "\n"; + LOG(ERROR) << "select() returned " << result << " errno " << errno << " " << strerror(errno) << "\n"; if (errno != EINTR) active_ = false; } @@ -116,23 +116,23 @@ static void DNSSD_API reg_reply(DNSServiceRef sdref, const DNSServiceFlags flags PublishBonjour* publishBonjour = (PublishBonjour*)context; (void)publishBonjour; // unused - logO << "Got a reply for service " << name << "." << regtype << domain << "\n"; + LOG(INFO) << "Got a reply for service " << name << "." << regtype << domain << "\n"; if (errorCode == kDNSServiceErr_NoError) { if (flags & kDNSServiceFlagsAdd) - logO << "Name now registered and active\n"; + LOG(INFO) << "Name now registered and active\n"; else - logO << "Name registration removed\n"; + LOG(INFO) << "Name registration removed\n"; } else if (errorCode == kDNSServiceErr_NameConflict) { /// TODO: Error handling - logO << "Name in use, please choose another\n"; + LOG(INFO) << "Name in use, please choose another\n"; exit(-1); } else - logO << "Error " << errorCode << "\n"; + LOG(INFO) << "Error " << errorCode << "\n"; if (!(flags & kDNSServiceFlagsMoreComing)) fflush(stdout); diff --git a/server/snapServer.cpp b/server/snapServer.cpp index 30e5b601..8cf927ab 100644 --- a/server/snapServer.cpp +++ b/server/snapServer.cpp @@ -97,7 +97,7 @@ int main(int argc, char* argv[]) } catch (const std::invalid_argument& e) { - logS(kLogErr) << "Exception: " << e.what() << std::endl; + SLOG(LOG_ERR) << "Exception: " << e.what() << std::endl; cout << "\n" << op << "\n"; exit(EXIT_FAILURE); } @@ -141,7 +141,12 @@ int main(int argc, char* argv[]) return 1; } - std::clog.rdbuf(new Log("snapserver", LOG_DAEMON)); + Log::init( + { + make_shared(LogPriority::info, LogSink::Type::all), //, "%Y-%m-%d %H-%M-%S [#prio]"), + make_shared("snapserver", LogPriority::debug, LogSink::Type::special) + } + ); signal(SIGHUP, signal_handler); signal(SIGTERM, signal_handler); @@ -173,7 +178,7 @@ int main(int argc, char* argv[]) processPriority = 19; if (processPriority != 0) setpriority(PRIO_PROCESS, 0, processPriority); - logS(kLogNotice) << "daemon started" << std::endl; + SLOG(LOG_NOTICE) << "daemon started" << std::endl; } #endif @@ -201,17 +206,17 @@ int main(int argc, char* argv[]) io_service.stop(); t.join(); - logO << "Stopping streamServer" << endl; + LOG(INFO) << "Stopping streamServer" << endl; streamServer->stop(); - logO << "done" << endl; + LOG(INFO) << "done" << endl; } catch (const std::exception& e) { - logS(kLogErr) << "Exception: " << e.what() << std::endl; + SLOG(LOG_ERR) << "Exception: " << e.what() << std::endl; exitcode = EXIT_FAILURE; } - logS(kLogNotice) << "daemon terminated." << endl; + SLOG(LOG_NOTICE) << "daemon terminated." << endl; exit(exitcode); } diff --git a/server/streamServer.cpp b/server/streamServer.cpp index d61b5054..92cff841 100644 --- a/server/streamServer.cpp +++ b/server/streamServer.cpp @@ -41,8 +41,8 @@ StreamServer::~StreamServer() void StreamServer::onStateChanged(const PcmStream* pcmStream, const ReaderState& state) { /// Notification: {"jsonrpc":"2.0","method":"Stream.OnUpdate","params":{"id":"stream 1","stream":{"id":"stream 1","status":"idle","uri":{"fragment":"","host":"","path":"/tmp/snapfifo","query":{"buffer_ms":"20","codec":"flac","name":"stream 1","sampleformat":"48000:16:2"},"raw":"pipe:///tmp/snapfifo?name=stream 1","scheme":"pipe"}}}} - logO << "onStateChanged (" << pcmStream->getName() << "): " << state << "\n"; -// logO << pcmStream->toJson().dump(4); + LOG(INFO) << "onStateChanged (" << pcmStream->getName() << "): " << state << "\n"; +// LOG(INFO) << pcmStream->toJson().dump(4); json notification = jsonrpcpp::Notification("Stream.OnUpdate", jsonrpcpp::Parameter("id", pcmStream->getId(), "stream", pcmStream->toJson())).to_json(); controlServer_->send(notification.dump(), NULL); ////cout << "Notification: " << notification.dump() << "\n"; @@ -51,7 +51,7 @@ void StreamServer::onStateChanged(const PcmStream* pcmStream, const ReaderState& void StreamServer::onChunkRead(const PcmStream* pcmStream, const msg::PcmChunk* chunk, double duration) { -// logO << "onChunkRead (" << pcmStream->getName() << "): " << duration << "ms\n"; +// LOG(INFO) << "onChunkRead (" << pcmStream->getName() << "): " << duration << "ms\n"; bool isDefaultStream(pcmStream == streamManager_->getDefaultStream().get()); std::shared_ptr shared_message(chunk); @@ -82,7 +82,7 @@ void StreamServer::onChunkRead(const PcmStream* pcmStream, const msg::PcmChunk* void StreamServer::onResync(const PcmStream* pcmStream, double ms) { - logO << "onResync (" << pcmStream->getName() << "): " << ms << "ms\n"; + LOG(INFO) << "onResync (" << pcmStream->getName() << "): " << ms << "ms\n"; } @@ -94,15 +94,15 @@ void StreamServer::onDisconnect(StreamSession* streamSession) if (session == nullptr) return; - logO << "onDisconnect: " << session->clientId << "\n"; - logD << "sessions: " << sessions_.size() << "\n"; + LOG(INFO) << "onDisconnect: " << session->clientId << "\n"; + LOG(DEBUG) << "sessions: " << sessions_.size() << "\n"; // don't block: remove StreamSession in a thread auto func = [](shared_ptr s)->void{s->stop();}; std::thread t(func, session); t.detach(); sessions_.erase(session); - logD << "sessions: " << sessions_.size() << "\n"; + LOG(DEBUG) << "sessions: " << sessions_.size() << "\n"; // notify controllers if not yet done ClientInfoPtr clientInfo = Config::instance().getClientInfo(streamSession->clientId); @@ -126,7 +126,7 @@ void StreamServer::ProcessRequest(const jsonrpcpp::request_ptr request, jsonrpcp { try { - ////logO << "StreamServer::ProcessRequest method: " << request->method << ", " << "id: " << request->id << "\n"; + ////LOG(INFO) << "StreamServer::ProcessRequest method: " << request->method << ", " << "id: " << request->id << "\n"; Json result; if (request->method.find("Client.") == 0) @@ -366,12 +366,12 @@ void StreamServer::ProcessRequest(const jsonrpcpp::request_ptr request, jsonrpcp } catch (const jsonrpcpp::RequestException& e) { - logE << "StreamServer::onMessageReceived JsonRequestException: " << e.to_json().dump() << ", message: " << request->to_json().dump() << "\n"; + LOG(ERROR) << "StreamServer::onMessageReceived JsonRequestException: " << e.to_json().dump() << ", message: " << request->to_json().dump() << "\n"; response.reset(new jsonrpcpp::RequestException(e)); } catch (const exception& e) { - logE << "StreamServer::onMessageReceived exception: " << e.what() << ", message: " << request->to_json().dump() << "\n"; + LOG(ERROR) << "StreamServer::onMessageReceived exception: " << e.what() << ", message: " << request->to_json().dump() << "\n"; response.reset(new jsonrpcpp::InternalErrorException(e.what(), request->id)); } } @@ -379,7 +379,7 @@ void StreamServer::ProcessRequest(const jsonrpcpp::request_ptr request, jsonrpcp void StreamServer::onMessageReceived(ControlSession* controlSession, const std::string& message) { - logD << "onMessageReceived: " << message << "\n"; + LOG(DEBUG) << "onMessageReceived: " << message << "\n"; jsonrpcpp::entity_ptr entity(nullptr); try { @@ -445,14 +445,14 @@ void StreamServer::onMessageReceived(ControlSession* controlSession, const std:: void StreamServer::onMessageReceived(StreamSession* connection, const msg::BaseMessage& baseMessage, char* buffer) { -// logD << "onMessageReceived: " << baseMessage.type << ", size: " << baseMessage.size << ", id: " << baseMessage.id << ", refers: " << baseMessage.refersTo << ", sent: " << baseMessage.sent.sec << "," << baseMessage.sent.usec << ", recv: " << baseMessage.received.sec << "," << baseMessage.received.usec << "\n"; +// LOG(DEBUG) << "onMessageReceived: " << baseMessage.type << ", size: " << baseMessage.size << ", id: " << baseMessage.id << ", refers: " << baseMessage.refersTo << ", sent: " << baseMessage.sent.sec << "," << baseMessage.sent.usec << ", recv: " << baseMessage.received.sec << "," << baseMessage.received.usec << "\n"; if (baseMessage.type == message_type::kTime) { msg::Time* timeMsg = new msg::Time(); timeMsg->deserialize(baseMessage, buffer); timeMsg->refersTo = timeMsg->id; timeMsg->latency = timeMsg->received - timeMsg->sent; -// logO << "Latency sec: " << timeMsg.latency.sec << ", usec: " << timeMsg.latency.usec << ", refers to: " << timeMsg.refersTo << "\n"; +// LOG(INFO) << "Latency sec: " << timeMsg.latency.sec << ", usec: " << timeMsg.latency.usec << ", refers to: " << timeMsg.refersTo << "\n"; connection->sendAsync(timeMsg, true); // refresh connection state @@ -468,11 +468,11 @@ void StreamServer::onMessageReceived(StreamSession* connection, const msg::BaseM msg::Hello helloMsg; helloMsg.deserialize(baseMessage, buffer); connection->clientId = helloMsg.getUniqueId(); - logO << "Hello from " << connection->clientId << ", host: " << helloMsg.getHostName() << ", v" << helloMsg.getVersion() + LOG(INFO) << "Hello from " << connection->clientId << ", host: " << helloMsg.getHostName() << ", v" << helloMsg.getVersion() << ", ClientName: " << helloMsg.getClientName() << ", OS: " << helloMsg.getOS() << ", Arch: " << helloMsg.getArch() << ", Protocol version: " << helloMsg.getProtocolVersion() << "\n"; - logD << "request kServerSettings: " << connection->clientId << "\n"; + LOG(DEBUG) << "request kServerSettings: " << connection->clientId << "\n"; // std::lock_guard mlock(mutex_); bool newGroup(false); GroupPtr group = Config::instance().getGroupFromClient(connection->clientId); @@ -484,7 +484,7 @@ void StreamServer::onMessageReceived(StreamSession* connection, const msg::BaseM ClientInfoPtr client = group->getClient(connection->clientId); - logD << "request kServerSettings\n"; + LOG(DEBUG) << "request kServerSettings\n"; msg::ServerSettings* serverSettings = new msg::ServerSettings(); serverSettings->setVolume(client->config.volume.percent); serverSettings->setMuted(client->config.volume.muted || group->muted); @@ -512,7 +512,7 @@ void StreamServer::onMessageReceived(StreamSession* connection, const msg::BaseM stream = streamManager_->getDefaultStream(); group->streamId = stream->getId(); } - logO << "Group: " << group->id << ", stream: " << group->streamId << "\n"; + LOG(DEBUG) << "Group: " << group->id << ", stream: " << group->streamId << "\n"; Config::instance().save(); @@ -556,7 +556,7 @@ session_ptr StreamServer::getStreamSession(StreamSession* streamSession) const session_ptr StreamServer::getStreamSession(const std::string& clientId) const { -// logO << "getStreamSession: " << mac << "\n"; +// LOG(INFO) << "getStreamSession: " << mac << "\n"; std::lock_guard mlock(sessionsMutex_); for (auto session: sessions_) { @@ -585,7 +585,7 @@ void StreamServer::handleAccept(socket_ptr socket) /// experimental: turn on tcp::no_delay socket->set_option(tcp::no_delay(true)); - logS(kLogNotice) << "StreamServer::NewConnection: " << socket->remote_endpoint().address().to_string() << endl; + SLOG(LOG_NOTICE) << "StreamServer::NewConnection: " << socket->remote_endpoint().address().to_string() << endl; shared_ptr session = make_shared(this, socket); session->setBufferMs(settings_.bufferMs); @@ -611,7 +611,7 @@ void StreamServer::start() { PcmStreamPtr stream = streamManager_->addStream(streamUri); if (stream) - logO << "Stream: " << stream->getUri().toJson() << "\n"; + LOG(INFO) << "Stream: " << stream->getUri().toJson() << "\n"; } streamManager_->start(); @@ -620,7 +620,7 @@ void StreamServer::start() } catch (const std::exception& e) { - logS(kLogNotice) << "StreamServer::start: " << e.what() << endl; + SLOG(LOG_NOTICE) << "StreamServer::start: " << e.what() << endl; stop(); throw; } diff --git a/server/streamSession.cpp b/server/streamSession.cpp index 8678b03c..8e9400d6 100644 --- a/server/streamSession.cpp +++ b/server/streamSession.cpp @@ -80,18 +80,18 @@ void StreamSession::stop() { std::lock_guard socketLock(socketMutex_); socket_->shutdown(asio::ip::tcp::socket::shutdown_both, ec); - if (ec) logE << "Error in socket shutdown: " << ec.message() << "\n"; + if (ec) LOG(ERROR) << "Error in socket shutdown: " << ec.message() << "\n"; socket_->close(ec); - if (ec) logE << "Error in socket close: " << ec.message() << "\n"; + if (ec) LOG(ERROR) << "Error in socket close: " << ec.message() << "\n"; } if (readerThread_ && readerThread_->joinable()) { - logD << "joining readerThread\n"; + LOG(DEBUG) << "joining readerThread\n"; readerThread_->join(); } if (writerThread_ && writerThread_->joinable()) { - logD << "joining writerThread\n"; + LOG(DEBUG) << "joining writerThread\n"; messages_.abort_wait(); writerThread_->join(); } @@ -103,7 +103,7 @@ void StreamSession::stop() readerThread_ = nullptr; writerThread_ = nullptr; socket_ = nullptr; - logD << "StreamSession stopped\n"; + LOG(DEBUG) << "StreamSession stopped\n"; } @@ -156,7 +156,7 @@ void StreamSession::setBufferMs(size_t bufferMs) bool StreamSession::send(const msg::BaseMessage* message) const { //TODO on exception: set active = false -// logO << "send: " << message->type << ", size: " << message->getSize() << ", id: " << message->id << ", refers: " << message->refersTo << "\n"; +// LOG(INFO) << "send: " << message->type << ", size: " << message->getSize() << ", id: " << message->id << ", refers: " << message->refersTo << "\n"; std::lock_guard socketLock(socketMutex_); { std::lock_guard activeLock(activeMutex_); @@ -169,7 +169,7 @@ bool StreamSession::send(const msg::BaseMessage* message) const message->sent = t; message->serialize(stream); asio::write(*socket_.get(), streambuf); -// logO << "done: " << message->type << ", size: " << message->size << ", id: " << message->id << ", refers: " << message->refersTo << "\n"; +// LOG(INFO) << "done: " << message->type << ", size: " << message->size << ", id: " << message->id << ", refers: " << message->refersTo << "\n"; return true; } @@ -183,11 +183,11 @@ void StreamSession::getNextMessage() baseMessage.deserialize(&buffer[0]); if (baseMessage.size > msg::max_size) { - logS(kLogErr) << "received message of type " << baseMessage.type << " to large: " << baseMessage.size << "\n"; + SLOG(LOG_ERR) << "received message of type " << baseMessage.type << " to large: " << baseMessage.size << "\n"; stop(); return; } -// logO << "getNextMessage: " << baseMessage.type << ", size: " << baseMessage.size << ", id: " << baseMessage.id << ", refers: " << baseMessage.refersTo << "\n"; +// LOG(INFO) << "getNextMessage: " << baseMessage.type << ", size: " << baseMessage.size << ", id: " << baseMessage.id << ", refers: " << baseMessage.refersTo << "\n"; if (baseMessage.size > buffer.size()) buffer.resize(baseMessage.size); // { @@ -213,7 +213,7 @@ void StreamSession::reader() } catch (const std::exception& e) { - logS(kLogErr) << "Exception in StreamSession::reader(): " << e.what() << endl; + SLOG(LOG_ERR) << "Exception in StreamSession::reader(): " << e.what() << endl; } if (active_ && (messageReceiver_ != NULL)) @@ -241,7 +241,7 @@ void StreamSession::writer() size_t age = 0; if (now > wireChunk->start()) age = std::chrono::duration_cast(now - wireChunk->start()).count(); - //logD << "PCM chunk. Age: " << age << ", buffer: " << bufferMs_ << ", age > buffer: " << (age > bufferMs_) << "\n"; + //LOG(DEBUG) << "PCM chunk. Age: " << age << ", buffer: " << bufferMs_ << ", age > buffer: " << (age > bufferMs_) << "\n"; if (age > bufferMs_) continue; } @@ -252,7 +252,7 @@ void StreamSession::writer() } catch (const std::exception& e) { - logS(kLogErr) << "Exception in StreamSession::writer(): " << e.what() << endl; + SLOG(LOG_ERR) << "Exception in StreamSession::writer(): " << e.what() << endl; } if (active_ && (messageReceiver_ != NULL)) diff --git a/server/streamreader/airplayStream.cpp b/server/streamreader/airplayStream.cpp index 6ebd3e63..44433040 100644 --- a/server/streamreader/airplayStream.cpp +++ b/server/streamreader/airplayStream.cpp @@ -72,17 +72,17 @@ void AirplayStream::onStderrMsg(const char* buffer, size_t n) string logmsg = utils::string::trim_copy(string(buffer, n)); if (logmsg.empty()) return; - logO << "(" << getName() << ") " << logmsg << "\n"; + LOG(INFO) << "(" << getName() << ") " << logmsg << "\n"; if (logmsg.find("Is another Shairport Sync running on this device") != string::npos) { - logE << "Seem there is another Shairport Sync runnig on port " << port_ << ", switching to port " << port_ + 1 << "\n"; + LOG(ERROR) << "Seem there is another Shairport Sync runnig on port " << port_ << ", switching to port " << port_ + 1 << "\n"; ++port_; params_ = params_wo_port_ + " --port=" + cpt::to_string(port_); } else if (logmsg.find("Invalid audio output specified") != string::npos) { - logE << "shairport sync compiled without stdout audio backend\n"; - logE << "build with: \"./configure --with-stdout --with-avahi --with-ssl=openssl --with-metadata\"\n"; + LOG(ERROR) << "shairport sync compiled without stdout audio backend\n"; + LOG(ERROR) << "build with: \"./configure --with-stdout --with-avahi --with-ssl=openssl --with-metadata\"\n"; } } diff --git a/server/streamreader/fileStream.cpp b/server/streamreader/fileStream.cpp index ec92100c..428cd974 100644 --- a/server/streamreader/fileStream.cpp +++ b/server/streamreader/fileStream.cpp @@ -36,7 +36,7 @@ FileStream::FileStream(PcmListener* pcmListener, const StreamUri& uri) : PcmStre ifs.open(uri_.path.c_str(), std::ifstream::in|std::ifstream::binary); if (!ifs.good()) { - logE << "failed to open PCM file: \"" + uri_.path + "\"\n"; + LOG(ERROR) << "failed to open PCM file: \"" + uri_.path + "\"\n"; throw SnapException("failed to open PCM file: \"" + uri_.path + "\""); } } @@ -91,7 +91,7 @@ void FileStream::worker() if (nextTick >= currentTick) { -// logO << "sleep: " << nextTick - currentTick << "\n"; +// LOG(INFO) << "sleep: " << nextTick - currentTick << "\n"; if (!sleep(nextTick - currentTick)) break; } @@ -106,7 +106,7 @@ void FileStream::worker() } catch(const std::exception& e) { - logE << "(FileStream) Exception: " << e.what() << std::endl; + LOG(ERROR) << "(FileStream) Exception: " << e.what() << std::endl; } } } diff --git a/server/streamreader/pcmStream.cpp b/server/streamreader/pcmStream.cpp index 901ddf31..7df3ab64 100644 --- a/server/streamreader/pcmStream.cpp +++ b/server/streamreader/pcmStream.cpp @@ -46,7 +46,7 @@ PcmStream::PcmStream(PcmListener* pcmListener, const StreamUri& uri) : if (uri_.query.find("sampleformat") == uri_.query.end()) throw SnapException("Stream URI must have a sampleformat"); sampleFormat_ = SampleFormat(uri_.query["sampleformat"]); - logO << "PcmStream sampleFormat: " << sampleFormat_.getFormat() << "\n"; + LOG(INFO) << "PcmStream sampleFormat: " << sampleFormat_.getFormat() << "\n"; if (uri_.query.find("buffer_ms") != uri_.query.end()) pcmReadMs_ = cpt::stoul(uri_.query["buffer_ms"]); @@ -91,7 +91,7 @@ const SampleFormat& PcmStream::getSampleFormat() const void PcmStream::start() { - logD << "PcmStream start: " << sampleFormat_.getFormat() << "\n"; + LOG(DEBUG) << "PcmStream start: " << sampleFormat_.getFormat() << "\n"; encoder_->init(this, sampleFormat_); active_ = true; thread_ = thread(&PcmStream::worker, this); @@ -138,7 +138,7 @@ void PcmStream::setState(const ReaderState& newState) void PcmStream::onChunkEncoded(const Encoder* encoder, msg::PcmChunk* chunk, double duration) { -// logO << "onChunkEncoded: " << duration << " us\n"; +// LOG(INFO) << "onChunkEncoded: " << duration << " us\n"; if (duration <= 0) return; diff --git a/server/streamreader/pipeStream.cpp b/server/streamreader/pipeStream.cpp index a0eb37af..878d0a11 100644 --- a/server/streamreader/pipeStream.cpp +++ b/server/streamreader/pipeStream.cpp @@ -39,7 +39,7 @@ PipeStream::PipeStream(PcmListener* pcmListener, const StreamUri& uri) : PcmStre umask(0); string mode = uri_.getQuery("mode", "create"); - logO << "PipeStream mode: " << mode << "\n"; + LOG(INFO) << "PipeStream mode: " << mode << "\n"; if ((mode != "read") && (mode != "create")) throw SnapException("create mode for fifo must be \"read\" or \"create\""); @@ -130,7 +130,7 @@ void PipeStream::worker() { if (lastException != e.what()) { - logE << "(PipeStream) Exception: " << e.what() << std::endl; + LOG(ERROR) << "(PipeStream) Exception: " << e.what() << std::endl; lastException = e.what(); } if (!sleep(100)) diff --git a/server/streamreader/processStream.cpp b/server/streamreader/processStream.cpp index 21e03726..86253e01 100644 --- a/server/streamreader/processStream.cpp +++ b/server/streamreader/processStream.cpp @@ -123,7 +123,7 @@ void ProcessStream::onStderrMsg(const char* buffer, size_t n) { string line = utils::string::trim_copy(string(buffer, n)); if ((line.find('\0') == string::npos) && !line.empty()) - logO << "(" << getName() << ") " << line << "\n"; + LOG(INFO) << "(" << getName() << ") " << line << "\n"; } } @@ -213,7 +213,7 @@ void ProcessStream::worker() { if (lastException != e.what()) { - logE << "(PipeStream) Exception: " << e.what() << std::endl; + LOG(ERROR) << "(PipeStream) Exception: " << e.what() << std::endl; lastException = e.what(); } process_->kill(); diff --git a/server/streamreader/spotifyStream.cpp b/server/streamreader/spotifyStream.cpp index d82974c9..83324849 100644 --- a/server/streamreader/spotifyStream.cpp +++ b/server/streamreader/spotifyStream.cpp @@ -51,7 +51,7 @@ SpotifyStream::SpotifyStream(PcmListener* pcmListener, const StreamUri& uri) : P params_ += " --onstart \"" + onstart + "\""; if (!onstop.empty()) params_ += " --onstop \"" + onstop + "\""; -// logO << "params: " << params << "\n"; +// LOG(INFO) << "params: " << params << "\n"; } @@ -108,7 +108,7 @@ void SpotifyStream::onStderrMsg(const char* buffer, size_t n) (logmsg.find('\0') == string::npos) && (logmsg.size() > 4)) { - logO << "(" << getName() << ") " << logmsg << "\n"; + LOG(INFO) << "(" << getName() << ") " << logmsg << "\n"; } } @@ -124,7 +124,7 @@ void SpotifyStream::stderrReader() void SpotifyStream::onTimeout(const Watchdog* watchdog, size_t ms) { - logE << "Spotify timeout: " << ms / 1000 << "\n"; + LOG(ERROR) << "Spotify timeout: " << ms / 1000 << "\n"; if (process_) process_->kill(); } diff --git a/server/streamreader/streamManager.cpp b/server/streamreader/streamManager.cpp index 4f17b384..c36bc0f9 100644 --- a/server/streamreader/streamManager.cpp +++ b/server/streamreader/streamManager.cpp @@ -49,11 +49,11 @@ PcmStreamPtr StreamManager::addStream(const std::string& uri) if (streamUri.query.find("buffer_ms") == streamUri.query.end()) streamUri.query["buffer_ms"] = cpt::to_string(readBufferMs_); -// logD << "\nURI: " << streamUri.uri << "\nscheme: " << streamUri.scheme << "\nhost: " +// LOG(DEBUG) << "\nURI: " << streamUri.uri << "\nscheme: " << streamUri.scheme << "\nhost: " // << streamUri.host << "\npath: " << streamUri.path << "\nfragment: " << streamUri.fragment << "\n"; // for (auto kv: streamUri.query) -// logD << "key: '" << kv.first << "' value: '" << kv.second << "'\n"; +// LOG(DEBUG) << "key: '" << kv.first << "' value: '" << kv.second << "'\n"; PcmStreamPtr stream(nullptr); if (streamUri.scheme == "pipe") diff --git a/server/streamreader/streamUri.cpp b/server/streamreader/streamUri.cpp index eeda6ade..9e72be36 100644 --- a/server/streamreader/streamUri.cpp +++ b/server/streamreader/streamUri.cpp @@ -31,7 +31,7 @@ StreamUri::StreamUri(const std::string& streamUri) // https://en.wikipedia.org/wiki/Uniform_Resource_Identifier // scheme:[//[user:password@]host[:port]][/]path[?query][#fragment] // would be more elegant with regex. Not yet supported on my dev machine's gcc 4.8 :( - logD << "StreamUri: " << streamUri << "\n"; + LOG(DEBUG) << "StreamUri: " << streamUri << "\n"; size_t pos; uri = strutils::trim_copy(streamUri); while (!uri.empty() && ((uri[0] == '\'') || (uri[0] == '"'))) @@ -40,7 +40,7 @@ StreamUri::StreamUri(const std::string& streamUri) uri = uri.substr(0, this->uri.length()-1); string decodedUri = strutils::uriDecode(uri); - logD << "StreamUri: " << decodedUri << "\n"; + LOG(DEBUG) << "StreamUri: " << decodedUri << "\n"; string tmp(decodedUri); @@ -49,7 +49,7 @@ StreamUri::StreamUri(const std::string& streamUri) throw invalid_argument("missing ':'"); scheme = strutils::trim_copy(tmp.substr(0, pos)); tmp = tmp.substr(pos + 1); - logD << "scheme: '" << scheme << "' tmp: '" << tmp << "'\n"; + LOG(DEBUG) << "scheme: '" << scheme << "' tmp: '" << tmp << "'\n"; if (tmp.find("//") != 0) throw invalid_argument("missing host separator: '//'"); @@ -61,7 +61,7 @@ StreamUri::StreamUri(const std::string& streamUri) host = strutils::trim_copy(tmp.substr(0, pos)); tmp = tmp.substr(pos); path = tmp; - logD << "host: '" << host << "' tmp: '" << tmp << "' path: '" << path << "'\n"; + LOG(DEBUG) << "host: '" << host << "' tmp: '" << tmp << "' path: '" << path << "'\n"; pos = tmp.find('?'); if (pos == string::npos) @@ -70,7 +70,7 @@ StreamUri::StreamUri(const std::string& streamUri) path = strutils::trim_copy(tmp.substr(0, pos)); tmp = tmp.substr(pos + 1); string queryStr = tmp; - logD << "path: '" << path << "' tmp: '" << tmp << "' query: '" << queryStr << "'\n"; + LOG(DEBUG) << "path: '" << path << "' tmp: '" << tmp << "' query: '" << queryStr << "'\n"; pos = tmp.find('#'); if (pos != string::npos) @@ -78,7 +78,7 @@ StreamUri::StreamUri(const std::string& streamUri) queryStr = tmp.substr(0, pos); tmp = tmp.substr(pos + 1); fragment = strutils::trim_copy(tmp); - logD << "query: '" << queryStr << "' fragment: '" << fragment << "' tmp: '" << tmp << "'\n"; + LOG(DEBUG) << "query: '" << queryStr << "' fragment: '" << fragment << "' tmp: '" << tmp << "'\n"; } vector keyValueList = strutils::split(queryStr, '&');