3pp-mirror/snapcast
1
0
Fork 0
mirror of https://github.com/badaix/snapcast.git synced 2025-05-01 03:07:33 +02:00
Code Issues Projects Releases Packages Wiki Activity

update logger

Browse source
This commit is contained in:
badaix 2017-07-24 18:59:49 +02:00
parent 2955b20e9d
commit ce55f15c02
36 changed files with 967 additions and 389 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

2
client/Makefile
View file

@ -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 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) ifeq ($(ENDIAN), BIG)
CXXFLAGS += -DIS_BIG_ENDIAN CXXFLAGS += -DIS_BIG_ENDIAN

34
client/browseZeroConf/browseAvahi.cpp
View file

@ -80,14 +80,14 @@ void BrowseAvahi::resolve_callback(
switch (event) switch (event)
{ {
case AVAHI_RESOLVER_FAILURE: 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; break;
case AVAHI_RESOLVER_FOUND: case AVAHI_RESOLVER_FOUND:
{ {
char a[AVAHI_ADDRESS_STR_MAX], *t; 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); avahi_address_snprint(a, sizeof(a), address);
browseAvahi->result_.host_ = host_name; browseAvahi->result_.host_ = host_name;
@ -97,15 +97,15 @@ void BrowseAvahi::resolve_callback(
browseAvahi->result_.valid_ = true; browseAvahi->result_.valid_ = true;
t = avahi_string_list_to_string(txt); t = avahi_string_list_to_string(txt);
logO << "\t" << host_name << ":" << port << " (" << a << ")\n"; LOG(INFO) << "\t" << host_name << ":" << port << " (" << a << ")\n";
logD << "\tTXT=" << t << "\n"; LOG(DEBUG) << "\tTXT=" << t << "\n";
logD << "\tProto=" << (int)protocol << "\n"; LOG(DEBUG) << "\tProto=" << (int)protocol << "\n";
logD << "\tcookie is " << avahi_string_list_get_service_cookie(txt) << "\n"; LOG(DEBUG) << "\tcookie is " << avahi_string_list_get_service_cookie(txt) << "\n";
logD << "\tis_local: " << !!(flags & AVAHI_LOOKUP_RESULT_LOCAL) << "\n"; LOG(DEBUG) << "\tis_local: " << !!(flags & AVAHI_LOOKUP_RESULT_LOCAL) << "\n";
logD << "\tour_own: " << !!(flags & AVAHI_LOOKUP_RESULT_OUR_OWN) << "\n"; LOG(DEBUG) << "\tour_own: " << !!(flags & AVAHI_LOOKUP_RESULT_OUR_OWN) << "\n";
logD << "\twide_area: " << !!(flags & AVAHI_LOOKUP_RESULT_WIDE_AREA) << "\n"; LOG(DEBUG) << "\twide_area: " << !!(flags & AVAHI_LOOKUP_RESULT_WIDE_AREA) << "\n";
logD << "\tmulticast: " << !!(flags & AVAHI_LOOKUP_RESULT_MULTICAST) << "\n"; LOG(DEBUG) << "\tmulticast: " << !!(flags & AVAHI_LOOKUP_RESULT_MULTICAST) << "\n";
logD << "\tcached: " << !!(flags & AVAHI_LOOKUP_RESULT_CACHED) << "\n"; LOG(DEBUG) << "\tcached: " << !!(flags & AVAHI_LOOKUP_RESULT_CACHED) << "\n";
avahi_free(t); avahi_free(t);
} }
} }
@ -135,12 +135,12 @@ void BrowseAvahi::browse_callback(
switch (event) switch (event)
{ {
case AVAHI_BROWSER_FAILURE: 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); avahi_simple_poll_quit(simple_poll);
return; return;
case AVAHI_BROWSER_NEW: 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 /* We ignore the returned resolver object. In the callback
function we free it. If the server is terminated before function we free it. If the server is terminated before
@ -148,17 +148,17 @@ void BrowseAvahi::browse_callback(
the resolver for us. */ the resolver for us. */
if (!(avahi_service_resolver_new(browseAvahi->client_, interface, protocol, name, type, domain, AVAHI_PROTO_UNSPEC, (AvahiLookupFlags)0, resolve_callback, userdata))) 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; break;
case AVAHI_BROWSER_REMOVE: 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; break;
case AVAHI_BROWSER_ALL_FOR_NOW: case AVAHI_BROWSER_ALL_FOR_NOW:
case AVAHI_BROWSER_CACHE_EXHAUSTED: 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; break;
} }
} }
@ -173,7 +173,7 @@ void BrowseAvahi::client_callback(AvahiClient *c, AvahiClientState state, AVAHI_
if (state == AVAHI_CLIENT_FAILURE) 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); avahi_simple_poll_quit(simple_poll);
} }
} }

2
client/browseZeroConf/browseBonjour.cpp
View file

@ -260,7 +260,7 @@ bool BrowseBonjour::browse(const string& serviceName, mDNSResult& result, int ti
return false; return false;
if (resultCollection.size() != 1) if (resultCollection.size() != 1)
logO << "Multiple servers found. Using first" << endl; LOG(NOTICE) << "Multiple servers found. Using first" << endl;
result = resultCollection[0]; result = resultCollection[0];

28
client/clientConnection.cpp
View file

@ -62,7 +62,7 @@ std::string ClientConnection::getMacAddress() const
std::string mac = ::getMacAddress(socket_->native_handle()); std::string mac = ::getMacAddress(socket_->native_handle());
if (mac.empty()) if (mac.empty())
mac = "00:00:00:00:00:00"; 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; return mac;
} }
@ -72,7 +72,7 @@ void ClientConnection::start()
tcp::resolver resolver(io_service_); tcp::resolver resolver(io_service_);
tcp::resolver::query query(tcp::v4(), host_, cpt::to_string(port_), asio::ip::resolver_query_base::numeric_service); tcp::resolver::query query(tcp::v4(), host_, cpt::to_string(port_), asio::ip::resolver_query_base::numeric_service);
auto iterator = resolver.resolve(query); auto iterator = resolver.resolve(query);
logO << "Connecting\n"; LOG(DEBUG) << "Connecting\n";
socket_.reset(new tcp::socket(io_service_)); socket_.reset(new tcp::socket(io_service_));
// struct timeval tv; // struct timeval tv;
// tv.tv_sec = 5; // tv.tv_sec = 5;
@ -82,7 +82,7 @@ void ClientConnection::start()
// setsockopt(socket->native_handle(), SOL_SOCKET, SO_SNDTIMEO, &tv, sizeof(tv)); // setsockopt(socket->native_handle(), SOL_SOCKET, SO_SNDTIMEO, &tv, sizeof(tv));
socket_->connect(*iterator); socket_->connect(*iterator);
connected_ = true; 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; active_ = true;
readerThread_ = new thread(&ClientConnection::reader, this); readerThread_ = new thread(&ClientConnection::reader, this);
} }
@ -98,13 +98,13 @@ void ClientConnection::stop()
if (socket_) if (socket_)
{ {
socket_->shutdown(asio::ip::tcp::socket::shutdown_both, ec); 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); 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_) if (readerThread_)
{ {
logD << "joining readerThread\n"; LOG(DEBUG) << "joining readerThread\n";
readerThread_->join(); readerThread_->join();
delete readerThread_; delete readerThread_;
} }
@ -114,18 +114,18 @@ void ClientConnection::stop()
} }
readerThread_ = NULL; readerThread_ = NULL;
socket_.reset(); socket_.reset();
logD << "readerThread terminated\n"; LOG(DEBUG) << "readerThread terminated\n";
} }
bool ClientConnection::send(const msg::BaseMessage* message) const bool ClientConnection::send(const msg::BaseMessage* message) const
{ {
// std::unique_lock<std::mutex> mlock(mutex_); // std::unique_lock<std::mutex> mlock(mutex_);
//logD << "send: " << message->type << ", size: " << message->getSize() << "\n"; //LOG(DEBUG) << "send: " << message->type << ", size: " << message->getSize() << "\n";
std::lock_guard<std::mutex> socketLock(socketMutex_); std::lock_guard<std::mutex> socketLock(socketMutex_);
if (!connected()) if (!connected())
return false; return false;
//logD << "send: " << message->type << ", size: " << message->getSize() << "\n"; //LOG(DEBUG) << "send: " << message->type << ", size: " << message->getSize() << "\n";
asio::streambuf streambuf; asio::streambuf streambuf;
std::ostream stream(&streambuf); std::ostream stream(&streambuf);
tv t; tv t;
@ -142,7 +142,7 @@ shared_ptr<msg::SerializedMessage> ClientConnection::sendRequest(const msg::Base
if (++reqId_ >= 10000) if (++reqId_ >= 10000)
reqId_ = 1; reqId_ = 1;
message->id = reqId_; message->id = reqId_;
// logO << "Req: " << message->id << "\n"; // LOG(INFO) << "Req: " << message->id << "\n";
shared_ptr<PendingRequest> pendingRequest(new PendingRequest(reqId_)); shared_ptr<PendingRequest> pendingRequest(new PendingRequest(reqId_));
std::unique_lock<std::mutex> lock(pendingRequestsMutex_); std::unique_lock<std::mutex> lock(pendingRequestsMutex_);
@ -152,12 +152,12 @@ shared_ptr<msg::SerializedMessage> ClientConnection::sendRequest(const msg::Base
{ {
response = pendingRequest->response; response = pendingRequest->response;
sumTimeout_ = chronos::msec(0); sumTimeout_ = chronos::msec(0);
// logO << "Resp: " << pendingRequest->id << "\n"; // LOG(INFO) << "Resp: " << pendingRequest->id << "\n";
} }
else else
{ {
sumTimeout_ += timeout; 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)) if (sumTimeout_ > chronos::sec(10))
throw SnapException("sum timeout exceeded 10s"); throw SnapException("sum timeout exceeded 10s");
} }
@ -173,7 +173,7 @@ void ClientConnection::getNextMessage()
vector<char> buffer(baseMsgSize); vector<char> buffer(baseMsgSize);
socketRead(&buffer[0], baseMsgSize); socketRead(&buffer[0], baseMsgSize);
baseMessage.deserialize(&buffer[0]); 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()) if (baseMessage.size > buffer.size())
buffer.resize(baseMessage.size); buffer.resize(baseMessage.size);
// { // {
@ -185,7 +185,7 @@ void ClientConnection::getNextMessage()
{ {
std::unique_lock<std::mutex> lock(pendingRequestsMutex_); std::unique_lock<std::mutex> 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_) for (auto req: pendingRequests_)
{ {

25
client/controller.cpp
View file

@ -50,7 +50,7 @@ Controller::Controller(const std::string& hostId, size_t instance) : MessageRece
void Controller::onException(ClientConnection* connection, const std::exception& exception) 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(); exception_ = exception.what();
asyncException_ = true; asyncException_ = true;
} }
@ -65,12 +65,12 @@ void Controller::onMessageReceived(ClientConnection* connection, const msg::Base
{ {
msg::PcmChunk* pcmChunk = new msg::PcmChunk(sampleFormat_, 0); msg::PcmChunk* pcmChunk = new msg::PcmChunk(sampleFormat_, 0);
pcmChunk->deserialize(baseMessage, buffer); 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)) if (decoder_->decode(pcmChunk))
{ {
//TODO: do decoding in thread? //TODO: do decoding in thread?
stream_->addChunk(pcmChunk); 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 else
delete pcmChunk; delete pcmChunk;
@ -86,7 +86,7 @@ void Controller::onMessageReceived(ClientConnection* connection, const msg::Base
{ {
serverSettings_.reset(new msg::ServerSettings()); serverSettings_.reset(new msg::ServerSettings());
serverSettings_->deserialize(baseMessage, buffer); 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_) if (stream_ && player_)
{ {
player_->setVolume(serverSettings_->getVolume() / 100.); player_->setVolume(serverSettings_->getVolume() / 100.);
@ -99,7 +99,7 @@ void Controller::onMessageReceived(ClientConnection* connection, const msg::Base
headerChunk_.reset(new msg::CodecHeader()); headerChunk_.reset(new msg::CodecHeader());
headerChunk_->deserialize(baseMessage, buffer); headerChunk_->deserialize(baseMessage, buffer);
logO << "Codec: " << headerChunk_->codec << "\n"; LOG(INFO) << "Codec: " << headerChunk_->codec << "\n";
decoder_.reset(nullptr); decoder_.reset(nullptr);
stream_ = nullptr; stream_ = nullptr;
player_.reset(nullptr); player_.reset(nullptr);
@ -116,7 +116,8 @@ void Controller::onMessageReceived(ClientConnection* connection, const msg::Base
throw SnapException("codec not supported: \"" + headerChunk_->codec + "\""); throw SnapException("codec not supported: \"" + headerChunk_->codec + "\"");
sampleFormat_ = decoder_->setHeader(headerChunk_.get()); 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<Stream>(sampleFormat_); stream_ = make_shared<Stream>(sampleFormat_);
stream_->setBufferLen(serverSettings_->getBufferMs() - latency_); stream_->setBufferLen(serverSettings_->getBufferMs() - latency_);
@ -137,7 +138,7 @@ void Controller::onMessageReceived(ClientConnection* connection, const msg::Base
if (baseMessage.type != message_type::kTime) if (baseMessage.type != message_type::kTime)
if (sendTimeSyncMessage(1000)) 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() void Controller::stop()
{ {
logD << "Stopping Controller" << endl; LOG(DEBUG) << "Stopping Controller" << endl;
active_ = false; active_ = false;
controllerThread_.join(); controllerThread_.join();
clientConnection_->stop(); clientConnection_->stop();
@ -202,7 +203,7 @@ void Controller::worker()
chronos::usleep(100); chronos::usleep(100);
} }
} }
logO << "diff to server [ms]: " << (float)TimeProvider::getInstance().getDiffToServer<chronos::usec>().count() / 1000.f << "\n"; LOG(INFO) << "diff to server [ms]: " << (float)TimeProvider::getInstance().getDiffToServer<chronos::usec>().count() / 1000.f << "\n";
/// Main loop /// Main loop
while (active_) while (active_)
@ -215,13 +216,13 @@ void Controller::worker()
} }
if (sendTimeSyncMessage(5000)) if (sendTimeSyncMessage(5000))
logO << "time sync main loop\n"; LOG(DEBUG) << "time sync main loop\n";
} }
} }
catch (const std::exception& e) catch (const std::exception& e)
{ {
asyncException_ = false; asyncException_ = false;
logS(kLogErr) << "Exception in Controller::worker(): " << e.what() << endl; SLOG(LOG_ERR) << "Exception in Controller::worker(): " << e.what() << endl;
clientConnection_->stop(); clientConnection_->stop();
player_.reset(); player_.reset();
stream_.reset(); stream_.reset();
@ -230,7 +231,7 @@ void Controller::worker()
chronos::sleep(100); chronos::sleep(100);
} }
} }
logD << "Thread stopped\n"; LOG(DEBUG) << "Thread stopped\n";
} }

8
client/decoder/flacDecoder.cpp
View file

@ -76,7 +76,7 @@ bool FlacDecoder::decode(msg::PcmChunk* chunk)
if (lastError_) if (lastError_)
{ {
logE << "FLAC decode error: " << FLAC__StreamDecoderErrorStatusString[*lastError_] << "\n"; LOG(ERROR) << "FLAC decode error: " << FLAC__StreamDecoderErrorStatusString[*lastError_] << "\n";
lastError_= nullptr; lastError_= nullptr;
return false; return false;
} }
@ -88,7 +88,7 @@ bool FlacDecoder::decode(msg::PcmChunk* chunk)
int32_t s = (diffMs / 1000); int32_t s = (diffMs / 1000);
int32_t us = (diffMs * 1000); int32_t us = (diffMs * 1000);
us %= 1000000; 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); chunk->timestamp = chunk->timestamp - tv(s, us);
} }
return true; return true;
@ -162,7 +162,7 @@ FLAC__StreamDecoderWriteStatus write_callback(const FLAC__StreamDecoder *decoder
{ {
if (buffer[channel] == NULL) 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; 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 error_callback(const FLAC__StreamDecoder *decoder, FLAC__StreamDecoderErrorStatus status, void *client_data)
{ {
(void)decoder, (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<FlacDecoder*>(client_data)->lastError_ = std::unique_ptr<FLAC__StreamDecoderErrorStatus>(new FLAC__StreamDecoderErrorStatus(status)); static_cast<FlacDecoder*>(client_data)->lastError_ = std::unique_ptr<FLAC__StreamDecoderErrorStatus>(new FLAC__StreamDecoderErrorStatus(status));
/// TODO, see issue #120: /// TODO, see issue #120:

6
client/decoder/oggDecoder.cpp
View file

@ -71,7 +71,7 @@ bool OggDecoder::decode(msg::PcmChunk* chunk)
if (result < 0) if (result < 0)
{ {
/* missing or corrupt data at this page position */ /* 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; continue;
} }
@ -229,11 +229,11 @@ SampleFormat OggDecoder::setHeader(msg::CodecHeader* chunk)
std::string comment(*ptr); std::string comment(*ptr);
if (comment.find("SAMPLE_FORMAT=") == 0) if (comment.find("SAMPLE_FORMAT=") == 0)
sampleFormat_.setFormat(comment.substr(comment.find("=") + 1)); sampleFormat_.setFormat(comment.substr(comment.find("=") + 1));
logO << "comment: " << comment << "\n";; LOG(INFO) << "comment: " << comment << "\n";;
++ptr; ++ptr;
} }
logO << "Encoded by: " << vc.vendor << "\n"; LOG(INFO) << "Encoded by: " << vc.vendor << "\n";
return sampleFormat_; return sampleFormat_;
} }

28
client/player/alsaPlayer.cpp
View file

@ -121,30 +121,30 @@ void AlsaPlayer::initAlsa()
// long unsigned int periodsize = stream_->format.msRate() * 50;//2*rate/50; // 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) // 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 */ /* Write parameters */
if ((pcm = snd_pcm_hw_params(handle_, params)) < 0) if ((pcm = snd_pcm_hw_params(handle_, params)) < 0)
throw SnapException("Can't set harware parameters: " + string(snd_strerror(pcm))); throw SnapException("Can't set harware parameters: " + string(snd_strerror(pcm)));
/* Resume information */ /* Resume information */
logD << "PCM name: " << snd_pcm_name(handle_) << "\n"; LOG(DEBUG) << "PCM name: " << snd_pcm_name(handle_) << "\n";
logD << "PCM state: " << snd_pcm_state_name(snd_pcm_state(handle_)) << "\n"; LOG(DEBUG) << "PCM state: " << snd_pcm_state_name(snd_pcm_state(handle_)) << "\n";
snd_pcm_hw_params_get_channels(params, &tmp); 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); 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 */ /* Allocate buffer to hold single period */
snd_pcm_hw_params_get_period_size(params, &frames_, 0); 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_size = frames_ * format.frameSize; //channels * 2 /* 2 -> sample size */;
buff_ = (char *) malloc(buff_size); buff_ = (char *) malloc(buff_size);
snd_pcm_hw_params_get_period_time(params, &tmp, NULL); 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_t *swparams;
snd_pcm_sw_params_alloca(&swparams); snd_pcm_sw_params_alloca(&swparams);
@ -210,7 +210,7 @@ void AlsaPlayer::worker()
} }
catch (const std::exception& e) catch (const std::exception& e)
{ {
logE << "Exception in initAlsa: " << e.what() << endl; LOG(ERROR) << "Exception in initAlsa: " << e.what() << endl;
chronos::sleep(100); chronos::sleep(100);
} }
} }
@ -218,7 +218,7 @@ void AlsaPlayer::worker()
// snd_pcm_avail_delay(handle_, &framesAvail, &framesDelay); // snd_pcm_avail_delay(handle_, &framesAvail, &framesDelay);
snd_pcm_delay(handle_, &framesDelay); snd_pcm_delay(handle_, &framesDelay);
chronos::usec delay((chronos::usec::rep) (1000 * (double) framesDelay / stream_->getFormat().msRate())); 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_)) if (stream_->getPlayerChunk(buff_, delay, frames_))
{ {
@ -226,24 +226,24 @@ void AlsaPlayer::worker()
adjustVolume(buff_, frames_); adjustVolume(buff_, frames_);
if ((pcm = snd_pcm_writei(handle_, buff_, frames_)) == -EPIPE) if ((pcm = snd_pcm_writei(handle_, buff_, frames_)) == -EPIPE)
{ {
logE << "XRUN\n"; LOG(ERROR) << "XRUN\n";
snd_pcm_prepare(handle_); snd_pcm_prepare(handle_);
} }
else if (pcm < 0) 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(); uninitAlsa();
} }
} }
else else
{ {
logO << "Failed to get chunk\n"; LOG(INFO) << "Failed to get chunk\n";
while (active_ && !stream_->waitForChunk(100)) while (active_ && !stream_->waitForChunk(100))
{ {
logD << "Waiting for chunk\n"; LOG(DEBUG) << "Waiting for chunk\n";
if ((handle_ != NULL) && (chronos::getTickCount() - lastChunkTick > 5000)) 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(); uninitAlsa();
stream_->clearChunks(); stream_->clearChunks();
} }

12
client/player/coreAudioPlayer.cpp
View file

@ -54,7 +54,7 @@ void CoreAudioPlayer::playerCallback(AudioQueueRef queue, AudioQueueBufferRef bu
size_t bufferedMs = bufferedFrames * 1000 / pubStream_->getFormat().rate + (ms_ * (NUM_BUFFERS - 1)); size_t bufferedMs = bufferedFrames * 1000 / pubStream_->getFormat().rate + (ms_ * (NUM_BUFFERS - 1));
/// 15ms DAC delay. Based on trying. /// 15ms DAC delay. Based on trying.
bufferedMs += 15; 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 /// 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); chronos::usec delay(bufferedMs * 1000);
@ -63,11 +63,11 @@ void CoreAudioPlayer::playerCallback(AudioQueueRef queue, AudioQueueBufferRef bu
{ {
if (chronos::getTickCount() - lastChunkTick > 5000) 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); uninitAudioQueue(queue);
return; return;
} }
// logO << "Failed to get chunk. Playing silence.\n"; // LOG(INFO) << "Failed to get chunk. Playing silence.\n";
memset(buffer, 0, buff_size_); memset(buffer, 0, buff_size_);
} }
else else
@ -98,7 +98,7 @@ void CoreAudioPlayer::worker()
} }
catch (const std::exception& e) catch (const std::exception& e)
{ {
logE << "Exception in worker: " << e.what() << "\n"; LOG(ERROR) << "Exception in worker: " << e.what() << "\n";
chronos::sleep(100); chronos::sleep(100);
} }
} }
@ -135,7 +135,7 @@ void CoreAudioPlayer::initAudioQueue()
frames_ = (sampleFormat.rate * ms_) / 1000; frames_ = (sampleFormat.rate * ms_) / 1000;
ms_ = frames_ * 1000 / sampleFormat.rate; ms_ = frames_ * 1000 / sampleFormat.rate;
buff_size_ = frames_ * sampleFormat.frameSize; 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]; AudioQueueBufferRef buffers[NUM_BUFFERS];
for (int i = 0; i < NUM_BUFFERS; i++) for (int i = 0; i < NUM_BUFFERS; i++)
@ -145,7 +145,7 @@ void CoreAudioPlayer::initAudioQueue()
callback(this, queue, buffers[i]); callback(this, queue, buffers[i]);
} }
logE << "CoreAudioPlayer::worker\n"; LOG(ERROR) << "CoreAudioPlayer::worker\n";
AudioQueueCreateTimeline(queue, &timeLine_); AudioQueueCreateTimeline(queue, &timeLine_);
AudioQueueStart(queue, NULL); AudioQueueStart(queue, NULL);
CFRunLoopRun(); CFRunLoopRun();

26
client/player/openslPlayer.cpp
View file

@ -71,7 +71,7 @@ void OpenslPlayer::playerCallback(SLAndroidSimpleBufferQueueItf bq)
{ {
if (bq != bqPlayerBufferQueue) if (bq != bqPlayerBufferQueue)
{ {
logE << "Wrong bq!\n"; LOG(ERROR) << "Wrong bq!\n";
return; return;
} }
@ -81,7 +81,7 @@ void OpenslPlayer::playerCallback(SLAndroidSimpleBufferQueueItf bq)
if (lastTick != 0) if (lastTick != 0)
{ {
diff = now - lastTick; 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) // if (diff <= 50)
// { // {
// usleep(1000 * (50 - diff)); // usleep(1000 * (50 - diff));
@ -92,7 +92,7 @@ void OpenslPlayer::playerCallback(SLAndroidSimpleBufferQueueItf bq)
*/ */
// size_t d = player->frames_ / 0.48d; // size_t d = player->frames_ / 0.48d;
// logE << "Delay: " << d << "\n"; // LOG(ERROR) << "Delay: " << d << "\n";
// SLAndroidSimpleBufferQueueState state; // SLAndroidSimpleBufferQueueState state;
// (*bq)->GetState(bq, &state); // (*bq)->GetState(bq, &state);
// cout << "bqPlayerCallback count: " << state.count << ", idx: " << state.index << "\n"; // cout << "bqPlayerCallback count: " << state.count << ", idx: " << state.index << "\n";
@ -101,7 +101,7 @@ void OpenslPlayer::playerCallback(SLAndroidSimpleBufferQueueItf bq)
// chronos::usec delay((250 - diff) * 1000); // chronos::usec delay((250 - diff) * 1000);
// while (active_ && !stream_->waitForChunk(100)) // while (active_ && !stream_->waitForChunk(100))
// logO << "Waiting for chunk\n"; // LOG(INFO) << "Waiting for chunk\n";
if (!active_) if (!active_)
return; return;
@ -109,7 +109,7 @@ void OpenslPlayer::playerCallback(SLAndroidSimpleBufferQueueItf bq)
chronos::usec delay(ms_ * 1000); chronos::usec delay(ms_ * 1000);
if (!pubStream_->getPlayerChunk(buffer[curBuffer], delay, frames_)) 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); memset(buffer[curBuffer], 0, buff_size);
} }
else else
@ -196,7 +196,7 @@ void OpenslPlayer::initOpensl()
frames_ = format.rate / (1000 / ms_);// * format.channels; // 1920; // 48000 * 2 / 50 // => 50ms frames_ = format.rate / (1000 / ms_);// * format.channels; // 1920; // 48000 * 2 / 50 // => 50ms
buff_size = frames_ * format.frameSize /* 2 -> sample size */; 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; SLresult result;
// create engine // create engine
@ -347,17 +347,17 @@ void OpenslPlayer::uninitOpensl()
// if (!active_) // if (!active_)
// return; // return;
logO << "uninitOpensl\n"; LOG(INFO) << "uninitOpensl\n";
SLresult result; SLresult result;
logO << "OpenSLWrap_Shutdown - stopping playback\n"; LOG(INFO) << "OpenSLWrap_Shutdown - stopping playback\n";
if (bqPlayerPlay != NULL) if (bqPlayerPlay != NULL)
{ {
result = (*bqPlayerPlay)->SetPlayState(bqPlayerPlay, SL_PLAYSTATE_STOPPED); result = (*bqPlayerPlay)->SetPlayState(bqPlayerPlay, SL_PLAYSTATE_STOPPED);
if (SL_RESULT_SUCCESS != result) 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) if (bqPlayerObject != NULL)
{ {
@ -368,7 +368,7 @@ void OpenslPlayer::uninitOpensl()
bqPlayerVolume = NULL; bqPlayerVolume = NULL;
} }
logO << "OpenSLWrap_Shutdown - deleting mix object\n"; LOG(INFO) << "OpenSLWrap_Shutdown - deleting mix object\n";
if (outputMixObject != NULL) if (outputMixObject != NULL)
{ {
@ -376,7 +376,7 @@ void OpenslPlayer::uninitOpensl()
outputMixObject = NULL; outputMixObject = NULL;
} }
logO << "OpenSLWrap_Shutdown - deleting engine object\n"; LOG(INFO) << "OpenSLWrap_Shutdown - deleting engine object\n";
if (engineObject != NULL) if (engineObject != NULL)
{ {
@ -391,7 +391,7 @@ void OpenslPlayer::uninitOpensl()
delete [] buffer[1]; delete [] buffer[1];
buffer[1] = NULL; buffer[1] = NULL;
logO << "OpenSLWrap_Shutdown - finished\n"; LOG(INFO) << "OpenSLWrap_Shutdown - finished\n";
active_ = false; active_ = false;
} }

2
client/player/player.cpp
View file

@ -89,7 +89,7 @@ void Player::setVolume(double volume)
double base = M_E; double base = M_E;
// double base = 10.; // double base = 10.;
volume_ = (pow(base, volume)-1) / (base-1); volume_ = (pow(base, volume)-1) / (base-1);
logD << "setVolume: " << volume << " => " << volume_ << "\n"; LOG(DEBUG) << "setVolume: " << volume << " => " << volume_ << "\n";
} }

21
client/snapClient.cpp
View file

@ -115,7 +115,7 @@ int main (int argc, char **argv)
} }
catch (const std::invalid_argument& e) 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"; cout << "\n" << op << "\n";
exit(EXIT_FAILURE); exit(EXIT_FAILURE);
} }
@ -153,7 +153,12 @@ int main (int argc, char **argv)
if (instance <= 0) if (instance <= 0)
std::invalid_argument("instance id must be >= 1"); std::invalid_argument("instance id must be >= 1");
std::clog.rdbuf(new Log("snapclient", LOG_DAEMON)); Log::init(
{
make_shared<LogSinkCout>(LogPriority::info, LogSink::Type::all), //, "%Y-%m-%d %H-%M-%S [#prio]"),
make_shared<LogSinkNative>("snapclient", LogPriority::debug, LogSink::Type::special)
}
);
signal(SIGHUP, signal_handler); signal(SIGHUP, signal_handler);
signal(SIGTERM, signal_handler); signal(SIGTERM, signal_handler);
@ -187,7 +192,7 @@ int main (int argc, char **argv)
processPriority = 19; processPriority = 19;
if (processPriority != 0) if (processPriority != 0)
setpriority(PRIO_PROCESS, 0, processPriority); setpriority(PRIO_PROCESS, 0, processPriority);
logS(kLogNotice) << "daemon started" << std::endl; SLOG(LOG_NOTICE) << "daemon started" << std::endl;
} }
#endif #endif
@ -213,13 +218,13 @@ int main (int argc, char **argv)
{ {
host = avahiResult.ip_; host = avahiResult.ip_;
port = avahiResult.port_; port = avahiResult.port_;
logO << "Found server " << host << ":" << port << "\n"; LOG(INFO) << "Found server " << host << ":" << port << "\n";
break; break;
} }
} }
catch (const std::exception& e) catch (const std::exception& e)
{ {
logS(kLogErr) << "Exception: " << e.what() << std::endl; SLOG(LOG_ERR) << "Exception: " << e.what() << std::endl;
} }
chronos::sleep(500); chronos::sleep(500);
} }
@ -229,7 +234,7 @@ int main (int argc, char **argv)
std::unique_ptr<Controller> controller(new Controller(hostIdValue.getValue(), instance)); std::unique_ptr<Controller> controller(new Controller(hostIdValue.getValue(), instance));
if (!g_terminated) if (!g_terminated)
{ {
logO << "Latency: " << latency << "\n"; LOG(INFO) << "Latency: " << latency << "\n";
controller->start(pcmDevice, host, port, latency); controller->start(pcmDevice, host, port, latency);
while(!g_terminated) while(!g_terminated)
chronos::sleep(100); chronos::sleep(100);
@ -238,11 +243,11 @@ int main (int argc, char **argv)
} }
catch (const std::exception& e) catch (const std::exception& e)
{ {
logS(kLogErr) << "Exception: " << e.what() << std::endl; SLOG(LOG_ERR) << "Exception: " << e.what() << std::endl;
exitcode = EXIT_FAILURE; exitcode = EXIT_FAILURE;
} }
logS(kLogNotice) << "daemon terminated." << endl; SLOG(LOG_NOTICE) << "daemon terminated." << endl;
exit(exitcode); exit(exitcode);
} }

46
client/stream.cpp
View file

@ -52,7 +52,7 @@ void Stream::setRealSampleRate(double sampleRate)
correctAfterXFrames_ = 0; correctAfterXFrames_ = 0;
else else
correctAfterXFrames_ = round((format_.rate / sampleRate) / (format_.rate / sampleRate - 1.)); 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<cs::msec>().count() > 10000) while (chunks_.size() * chunk->duration<cs::msec>().count() > 10000)
chunks_.pop(); chunks_.pop();
chunks_.push(shared_ptr<msg::PcmChunk>(chunk)); chunks_.push(shared_ptr<msg::PcmChunk>(chunk));
// logD << "new chunk: " << chunk->duration<cs::msec>().count() << ", Chunks: " << chunks_.size() << "\n"; // LOG(DEBUG) << "new chunk: " << chunk->duration<cs::msec>().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()))// while (to > chunk_->timePoint())// + std::chrono::milliseconds((long int)chunk_->getDuration()))//
{ {
chunk_ = chunks_.pop(); chunk_ = chunks_.pop();
logD << "\nto: " << Chunk::getAge(to) << "\t chunk: " << Chunk::getAge(chunk_->timePoint()) << "\n"; LOG(DEBUG) << "\nto: " << Chunk::getAge(to) << "\t chunk: " << Chunk::getAge(chunk_->timePoint()) << "\n";
logD << "diff: " << std::chrono::duration_cast<std::chrono::milliseconds>((to - chunk_->timePoint())).count() << "\n"; LOG(DEBUG) << "diff: " << std::chrono::duration_cast<std::chrono::milliseconds>((to - chunk_->timePoint())).count() << "\n";
} }
chunk_->seek(std::chrono::duration_cast<std::chrono::milliseconds>(to - chunk_->timePoint()).count() * format_.msRate()); chunk_->seek(std::chrono::duration_cast<std::chrono::milliseconds>(to - chunk_->timePoint()).count() * format_.msRate());
return chunk_->timePoint(); 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_); float factor = (float)toRead / framesPerBuffer;//(float)(framesPerBuffer*channels_);
// if (abs(framesCorrection) > 1) // if (abs(framesCorrection) > 1)
// logO << "correction: " << framesCorrection << ", factor: " << factor << "\n"; // LOG(INFO) << "correction: " << framesCorrection << ", factor: " << factor << "\n";
float idx = 0; float idx = 0;
for (size_t n=0; n<framesPerBuffer; ++n) for (size_t n=0; n<framesPerBuffer; ++n)
{ {
@ -200,14 +200,14 @@ bool Stream::getPlayerChunk(void* outputBuffer, const cs::usec& outputBufferDacT
{ {
if (outputBufferDacTime > bufferMs_) if (outputBufferDacTime > bufferMs_)
{ {
logO << "outputBufferDacTime > bufferMs: " << cs::duration<cs::msec>(outputBufferDacTime) << " > " << cs::duration<cs::msec>(bufferMs_) << "\n"; LOG(INFO) << "outputBufferDacTime > bufferMs: " << cs::duration<cs::msec>(outputBufferDacTime) << " > " << cs::duration<cs::msec>(bufferMs_) << "\n";
sleep_ = cs::usec(0); sleep_ = cs::usec(0);
return false; return false;
} }
if (!chunk_ && !chunks_.try_pop(chunk_, outputBufferDacTime)) if (!chunk_ && !chunks_.try_pop(chunk_, outputBufferDacTime))
{ {
//logO << "no chunks available\n"; //LOG(INFO) << "no chunks available\n";
sleep_ = cs::usec(0); sleep_ = cs::usec(0);
return false; return false;
} }
@ -220,19 +220,19 @@ bool Stream::getPlayerChunk(void* outputBuffer, const cs::usec& outputBufferDacT
/// age < 0 => play in -age /// age < 0 => play in -age
/// age > 0 => too old /// age > 0 => too old
cs::usec age = std::chrono::duration_cast<cs::usec>(TimeProvider::serverNow() - chunk_->start()) - bufferMs_ + outputBufferDacTime; cs::usec age = std::chrono::duration_cast<cs::usec>(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))) if ((sleep_.count() == 0) && (cs::abs(age) > cs::msec(200)))
{ {
logO << "age > 200: " << cs::duration<cs::msec>(age) << "\n"; LOG(INFO) << "age > 200: " << cs::duration<cs::msec>(age) << "\n";
sleep_ = age; sleep_ = age;
} }
try 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())); 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); cs::usec correction = cs::usec(0);
if (sleep_.count() != 0) if (sleep_.count() != 0)
@ -240,24 +240,24 @@ bool Stream::getPlayerChunk(void* outputBuffer, const cs::usec& outputBufferDacT
resetBuffers(); resetBuffers();
if (sleep_ < -bufferDuration/2) if (sleep_ < -bufferDuration/2)
{ {
logO << "sleep < -bufferDuration/2: " << cs::duration<cs::msec>(sleep_) << " < " << -cs::duration<cs::msec>(bufferDuration)/2 << ", "; LOG(INFO) << "sleep < -bufferDuration/2: " << cs::duration<cs::msec>(sleep_) << " < " << -cs::duration<cs::msec>(bufferDuration)/2 << ", ";
// We're early: not enough chunks_. play silence. Reference chunk_ is the oldest (front) one // We're early: not enough chunks_. play silence. Reference chunk_ is the oldest (front) one
sleep_ = chrono::duration_cast<cs::usec>(TimeProvider::serverNow() - getSilentPlayerChunk(outputBuffer, framesPerBuffer) - bufferMs_ + outputBufferDacTime); sleep_ = chrono::duration_cast<cs::usec>(TimeProvider::serverNow() - getSilentPlayerChunk(outputBuffer, framesPerBuffer) - bufferMs_ + outputBufferDacTime);
logO << "sleep: " << cs::duration<cs::msec>(sleep_) << "\n"; LOG(INFO) << "sleep: " << cs::duration<cs::msec>(sleep_) << "\n";
if (sleep_ < -bufferDuration/2) if (sleep_ < -bufferDuration/2)
return true; return true;
} }
else if (sleep_ > bufferDuration/2) else if (sleep_ > bufferDuration/2)
{ {
logO << "sleep > bufferDuration/2: " << cs::duration<cs::msec>(sleep_) << " > " << cs::duration<cs::msec>(bufferDuration)/2 << "\n"; LOG(INFO) << "sleep > bufferDuration/2: " << cs::duration<cs::msec>(sleep_) << " > " << cs::duration<cs::msec>(bufferDuration)/2 << "\n";
// We're late: discard oldest chunks // We're late: discard oldest chunks
while (sleep_ > chunk_->duration<cs::usec>()) while (sleep_ > chunk_->duration<cs::usec>())
{ {
logO << "sleep > chunkDuration: " << cs::duration<cs::msec>(sleep_) << " > " << chunk_->duration<cs::msec>().count() << ", chunks: " << chunks_.size() << ", out: " << cs::duration<cs::msec>(outputBufferDacTime) << ", needed: " << cs::duration<cs::msec>(bufferDuration) << "\n"; LOG(INFO) << "sleep > chunkDuration: " << cs::duration<cs::msec>(sleep_) << " > " << chunk_->duration<cs::msec>().count() << ", chunks: " << chunks_.size() << ", out: " << cs::duration<cs::msec>(outputBufferDacTime) << ", needed: " << cs::duration<cs::msec>(bufferDuration) << "\n";
sleep_ = std::chrono::duration_cast<cs::usec>(TimeProvider::serverNow() - chunk_->start() - bufferMs_ + outputBufferDacTime); sleep_ = std::chrono::duration_cast<cs::usec>(TimeProvider::serverNow() - chunk_->start() - bufferMs_ + outputBufferDacTime);
if (!chunks_.try_pop(chunk_, outputBufferDacTime)) if (!chunks_.try_pop(chunk_, outputBufferDacTime))
{ {
logO << "no chunks available\n"; LOG(INFO) << "no chunks available\n";
chunk_ = NULL; chunk_ = NULL;
sleep_ = cs::usec(0); sleep_ = cs::usec(0);
return false; return false;
@ -278,7 +278,7 @@ bool Stream::getPlayerChunk(void* outputBuffer, const cs::usec& outputBufferDacT
} }
else else
{ {
logO << "Sleep " << cs::duration<cs::msec>(sleep_) << "\n"; LOG(INFO) << "Sleep " << cs::duration<cs::msec>(sleep_) << "\n";
correction = sleep_; correction = sleep_;
sleep_ = cs::usec(0); 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)) 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_); sleep_ = cs::usec(median_);
} }
/* else if (cs::usec(median_) > cs::usec(300)) /* 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)) 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_); sleep_ = cs::usec(shortMedian_);
} }
/* else /* 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))) 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()); sleep_ = cs::usec((cs::msec::rep)miniBuffer_.mean());
} }
} }
@ -341,7 +341,7 @@ bool Stream::getPlayerChunk(void* outputBuffer, const cs::usec& outputBufferDacT
if (lastAge != msAge) if (lastAge != msAge)
{ {
lastAge = msAge; lastAge = msAge;
logO << "Sleep " << cs::duration<cs::msec>(sleep_) << ", age: " << msAge << ", bufferDuration: " << cs::duration<cs::msec>(bufferDuration) << "\n"; LOG(INFO) << "Sleep " << cs::duration<cs::msec>(sleep_) << ", age: " << msAge << ", bufferDuration: " << cs::duration<cs::msec>(bufferDuration) << "\n";
} }
} }
else if (shortBuffer_.full()) else if (shortBuffer_.full())
@ -361,8 +361,8 @@ bool Stream::getPlayerChunk(void* outputBuffer, const cs::usec& outputBufferDacT
lastUpdate_ = now; lastUpdate_ = now;
median_ = buffer_.median(); median_ = buffer_.median();
shortMedian_ = shortBuffer_.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<cs::msec>(outputBufferDacTime) << "\n"; LOG(INFO) << "Chunk: " << age.count()/100 << "\t" << miniBuffer_.median()/100 << "\t" << shortMedian_/100 << "\t" << median_/100 << "\t" << buffer_.size() << "\t" << cs::duration<cs::msec>(outputBufferDacTime) << "\n";
// logO << "Chunk: " << age.count()/1000 << "\t" << miniBuffer_.median()/1000 << "\t" << shortMedian_/1000 << "\t" << median_/1000 << "\t" << buffer_.size() << "\t" << cs::duration<cs::msec>(outputBufferDacTime) << "\n"; // LOG(INFO) << "Chunk: " << age.count()/1000 << "\t" << miniBuffer_.median()/1000 << "\t" << shortMedian_/1000 << "\t" << median_/1000 << "\t" << buffer_.size() << "\t" << cs::duration<cs::msec>(outputBufferDacTime) << "\n";
} }
return (abs(cs::duration<cs::msec>(age)) < 500); return (abs(cs::duration<cs::msec>(age)) < 500);
} }

4
client/timeProvider.cpp
View file

@ -43,7 +43,7 @@ void TimeProvider::setDiffToServer(double ms)
/// clear diffBuffer if last update is older than a minute /// clear diffBuffer if last update is older than a minute
if (!diffBuffer_.empty() && (std::abs(now.tv_sec - lastTimeSync) > 60)) 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; diffToServer_ = ms*1000;
diffBuffer_.clear(); diffBuffer_.clear();
} }
@ -51,7 +51,7 @@ void TimeProvider::setDiffToServer(double ms)
diffBuffer_.add(ms*1000); diffBuffer_.add(ms*1000);
diffToServer_ = diffBuffer_.median(3); diffToServer_ = diffBuffer_.median(3);
// logO << "setDiffToServer: " << ms << ", diff: " << diffToServer_ / 1000.f << "\n"; // LOG(INFO) << "setDiffToServer: " << ms << ", diff: " << diffToServer_ / 1000.f << "\n";
} }
/* /*

132
common/log.cpp
View file

@ -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 <http://www.gnu.org/licenses/>.
***/
#include "log.h"
#include <iomanip>
#include <ctime>
#include <sstream>
#include <cstdio>
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<char>(c);
if (c == '\n')
sync();
}
else
{
sync();
}
return c;
}
std::ostream& operator<< (std::ostream& os, const LogPriority& log_priority)
{
static_cast<Log*>(os.rdbuf())->priority_ = log_priority;
return os;
}

759
common/log.h
View file

@ -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 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 it under the terms of the GNU General Public License as published by
@ -16,57 +23,749 @@
along with this program. If not, see <http://www.gnu.org/licenses/>. along with this program. If not, see <http://www.gnu.org/licenses/>.
***/ ***/
/// inspired by "eater":
/// https://stackoverflow.com/questions/2638654/redirect-c-stdclog-to-syslog-on-unix
#ifndef LOG_H /// TODO: add global log level
#define LOG_H
#include <syslog.h>
#ifndef AIX_LOG_HPP
#define AIX_LOG_HPP
#include <algorithm>
#include <chrono>
#include <cstdio>
#include <functional>
#include <iostream> #include <iostream>
#include <cstring> #include <memory>
#include <sstream> #include <sstream>
#include <vector>
#ifdef __ANDROID__
#include <android/log.h>
#endif
#ifdef __APPLE__
#include <os/log.h>
#endif
#ifdef _WIN32
#include <Windows.h>
#else
#include <syslog.h>
#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 normal,
kLogAlert = LOG_ALERT, // action must be taken immediately special
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
}; };
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<std::chrono::system_clock> 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<LogSink> log_sink_ptr;
class Log : public std::basic_streambuf<char, std::char_traits<char> > class Log : public std::basic_streambuf<char, std::char_traits<char> >
{ {
public: 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_sink_ptr> 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: protected:
int sync(); Log() : type_(LogType::normal)
int overflow(int c); {
}
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<char>(c);
}
else
{
std::cout << "EOF\n";
sync();
}
return c;
}
private: private:
friend std::ostream& operator<< (std::ostream& os, const LogPriority& log_priority); friend std::ostream& operator<< (std::ostream& os, const LogPriority& log_priority);
std::string toString(LogPriority logPriority) const; friend std::ostream& operator<< (std::ostream& os, const LogType& log_type);
std::string Timestamp() const; friend std::ostream& operator<< (std::ostream& os, const Tag& tag);
friend std::ostream& operator<< (std::ostream& os, const Conditional& conditional);
std::stringstream buffer_; std::stringstream buffer_;
int facility_;
LogPriority priority_; LogPriority priority_;
char ident_[50]; LogType type_;
Tag tag_;
Conditional conditional_;
std::vector<log_sink_ptr> 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<std::chrono::milliseconds>(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 #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<LogSinkAndroid>(ident_, priority, type);
#elif __APPLE__
log_sink_ = std::make_shared<LogSinkUnifiedLogging>(priority, type);
#elif _WIN32
log_sink_ = std::make_shared<LogSinkEventLog>(priority, type);
#else
log_sink_ = std::make_shared<LogSinkSyslog>(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<void(const time_point_sys_clock& timestamp, LogPriority priority, LogType type, const Tag& tag, const std::string& message)> 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<Log*>(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<Log*>(os.rdbuf());
if (log)
log->type_ = log_type;
return os;
}
static std::ostream& operator<< (std::ostream& os, const Tag& tag)
{
Log* log = dynamic_cast<Log*>(os.rdbuf());
if (log)
log->tag_ = tag;
return os;
}
static std::ostream& operator<< (std::ostream& os, const Conditional& conditional)
{
Log* log = dynamic_cast<Log*>(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

2
common/sampleFormat.cpp
View file

@ -79,7 +79,7 @@ void SampleFormat::setFormat(uint32_t rate, uint16_t bits, uint16_t channels)
if (bits == 24) if (bits == 24)
sampleSize = 4; sampleSize = 4;
frameSize = channels*sampleSize; frameSize = channels*sampleSize;
// logD << "SampleFormat: " << rate << ":" << bits << ":" << channels << "\n"; // LOG(DEBUG) << "SampleFormat: " << rate << ":" << bits << ":" << channels << "\n";
} }

2
server/Makefile
View file

@ -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 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 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) ifeq ($(ENDIAN), BIG)

8
server/config.cpp
View file

@ -48,15 +48,15 @@ Config::Config()
throw SnapException("failed to create settings directory: \"" + dir + "\": " + cpt::to_string(errno)); throw SnapException("failed to create settings directory: \"" + dir + "\": " + cpt::to_string(errno));
filename_ = dir + "server.json"; filename_ = dir + "server.json";
logS(kLogNotice) << "Settings file: \"" << filename_ << "\"\n"; SLOG(LOG_NOTICE) << "Settings file: \"" << filename_ << "\"\n";
int fd; int fd;
if ((fd = open(filename_.c_str(), O_RDWR | O_CREAT, S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH)) == -1) if ((fd = open(filename_.c_str(), O_RDWR | O_CREAT, S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH)) == -1)
{ {
if (errno == EACCES) 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 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); close(fd);
@ -83,7 +83,7 @@ Config::Config()
} }
catch(const std::exception& e) catch(const std::exception& e)
{ {
logE << "Error reading config: " << e.what() << "\n"; LOG(ERROR) << "Error reading config: " << e.what() << "\n";
} }
} }

6
server/controlServer.cpp
View file

@ -48,7 +48,7 @@ void ControlServer::cleanup()
{ {
if (!(*it)->active()) if (!(*it)->active())
{ {
logS(kLogErr) << "Session inactive. Removing\n"; SLOG(LOG_ERR) << "Session inactive. Removing\n";
// don't block: remove ClientSession in a thread // don't block: remove ClientSession in a thread
auto func = [](shared_ptr<ControlSession> s)->void{s->stop();}; auto func = [](shared_ptr<ControlSession> s)->void{s->stop();};
std::thread t(func, *it); 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) void ControlServer::onMessageReceived(ControlSession* connection, const std::string& message)
{ {
std::lock_guard<std::recursive_mutex> mlock(mutex_); std::lock_guard<std::recursive_mutex> mlock(mutex_);
logD << "received: \"" << message << "\"\n"; LOG(DEBUG) << "received: \"" << message << "\"\n";
if ((message == "quit") || (message == "exit") || (message == "bye")) if ((message == "quit") || (message == "exit") || (message == "bye"))
{ {
for (auto it = sessions_.begin(); it != sessions_.end(); ++it) 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_RCVTIMEO, &tv, sizeof(tv));
setsockopt(socket->native_handle(), SOL_SOCKET, SO_SNDTIMEO, &tv, sizeof(tv)); setsockopt(socket->native_handle(), SOL_SOCKET, SO_SNDTIMEO, &tv, sizeof(tv));
// socket->set_option(boost::asio::ip::tcp::no_delay(false)); // 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<ControlSession> session = make_shared<ControlSession>(this, socket); shared_ptr<ControlSession> session = make_shared<ControlSession>(this, socket);
{ {
std::lock_guard<std::recursive_mutex> mlock(mutex_); std::lock_guard<std::recursive_mutex> mlock(mutex_);

20
server/controlSession.cpp
View file

@ -52,7 +52,7 @@ void ControlSession::start()
void ControlSession::stop() void ControlSession::stop()
{ {
logD << "ControlSession::stop\n"; LOG(DEBUG) << "ControlSession::stop\n";
std::lock_guard<std::recursive_mutex> activeLock(activeMutex_); std::lock_guard<std::recursive_mutex> activeLock(activeMutex_);
active_ = false; active_ = false;
try try
@ -62,18 +62,18 @@ void ControlSession::stop()
{ {
std::lock_guard<std::recursive_mutex> socketLock(socketMutex_); std::lock_guard<std::recursive_mutex> socketLock(socketMutex_);
socket_->shutdown(asio::ip::tcp::socket::shutdown_both, ec); 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); 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()) if (readerThread_.joinable())
{ {
logD << "joining readerThread\n"; LOG(DEBUG) << "joining readerThread\n";
readerThread_.join(); readerThread_.join();
} }
if (writerThread_.joinable()) if (writerThread_.joinable())
{ {
logD << "joining writerThread\n"; LOG(DEBUG) << "joining writerThread\n";
messages_.abort_wait(); messages_.abort_wait();
writerThread_.join(); writerThread_.join();
} }
@ -82,7 +82,7 @@ void ControlSession::stop()
{ {
} }
socket_ = NULL; 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 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<std::recursive_mutex> socketLock(socketMutex_); std::lock_guard<std::recursive_mutex> socketLock(socketMutex_);
{ {
std::lock_guard<std::recursive_mutex> activeLock(activeMutex_); std::lock_guard<std::recursive_mutex> activeLock(activeMutex_);
@ -106,7 +106,7 @@ bool ControlSession::send(const std::string& message) const
std::ostream request_stream(&streambuf); std::ostream request_stream(&streambuf);
request_stream << message << "\r\n"; request_stream << message << "\r\n";
asio::write(*socket_.get(), streambuf); asio::write(*socket_.get(), streambuf);
//logO << "done\n"; //LOG(INFO) << "done\n";
return true; return true;
} }
@ -145,7 +145,7 @@ void ControlSession::reader()
} }
catch (const std::exception& e) 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; active_ = false;
} }
@ -166,7 +166,7 @@ void ControlSession::writer()
} }
catch (const std::exception& e) 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; active_ = false;
} }

6
server/encoder/flacEncoder.cpp
View file

@ -71,7 +71,7 @@ void FlacEncoder::encode(const msg::PcmChunk* chunk)
{ {
int samples = chunk->getSampleCount(); int samples = chunk->getSampleCount();
int frames = chunk->getFrameCount(); int frames = chunk->getFrameCount();
// logO << "payload: " << chunk->payloadSize << "\tframes: " << frames << "\tsamples: " << samples << "\tduration: " << chunk->duration<chronos::msec>().count() << "\n"; // LOG(INFO) << "payload: " << chunk->payloadSize << "\tframes: " << frames << "\tsamples: " << samples << "\tduration: " << chunk->duration<chronos::msec>().count() << "\n";
if (pcmBufferSize_ < samples) if (pcmBufferSize_ < samples)
{ {
@ -104,7 +104,7 @@ void FlacEncoder::encode(const msg::PcmChunk* chunk)
if (encodedSamples_ > 0) if (encodedSamples_ > 0)
{ {
double resMs = encodedSamples_ / ((double)sampleFormat_.rate / 1000.); 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; encodedSamples_ = 0;
listener_->onChunkEncoded(this, flacChunk_, resMs); listener_->onChunkEncoded(this, flacChunk_, resMs);
flacChunk_ = new msg::PcmChunk(chunk->format, 0); flacChunk_ = new msg::PcmChunk(chunk->format, 0);
@ -118,7 +118,7 @@ FLAC__StreamEncoderWriteStatus FlacEncoder::write_callback(const FLAC__StreamEnc
unsigned samples, unsigned samples,
unsigned current_frame) 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)) if ((current_frame == 0) && (bytes > 0) && (samples == 0))
{ {
headerChunk_->payload = (char*)realloc(headerChunk_->payload, headerChunk_->payloadSize + bytes); headerChunk_->payload = (char*)realloc(headerChunk_->payload, headerChunk_->payloadSize + bytes);

6
server/encoder/oggEncoder.cpp
View file

@ -55,7 +55,7 @@ std::string OggEncoder::name() const
void OggEncoder::encode(const msg::PcmChunk* chunk) void OggEncoder::encode(const msg::PcmChunk* chunk)
{ {
double res = 0; double res = 0;
logD << "payload: " << chunk->payloadSize << "\tframes: " << chunk->getFrameCount() << "\tduration: " << chunk->duration<chronos::msec>().count() << "\n"; LOG(DEBUG) << "payload: " << chunk->payloadSize << "\tframes: " << chunk->getFrameCount() << "\tduration: " << chunk->duration<chronos::msec>().count() << "\n";
int frames = chunk->getFrameCount(); int frames = chunk->getFrameCount();
float **buffer=vorbis_analysis_buffer(&vd_, frames); float **buffer=vorbis_analysis_buffer(&vd_, frames);
@ -129,7 +129,7 @@ void OggEncoder::encode(const msg::PcmChunk* chunk)
if (res > 0) if (res > 0)
{ {
res /= (sampleFormat_.rate / 1000.); res /= (sampleFormat_.rate / 1000.);
// logO << "res: " << res << "\n"; // LOG(INFO) << "res: " << res << "\n";
lastGranulepos_ = os_.granulepos; lastGranulepos_ = os_.granulepos;
// make oggChunk smaller // make oggChunk smaller
oggChunk->payload = (char*)realloc(oggChunk->payload, pos); oggChunk->payload = (char*)realloc(oggChunk->payload, pos);
@ -249,7 +249,7 @@ void OggEncoder::initEncoder()
break; break;
headerChunk_->payloadSize += og_.header_len + og_.body_len; headerChunk_->payloadSize += og_.header_len + og_.body_len;
headerChunk_->payload = (char*)realloc(headerChunk_->payload, headerChunk_->payloadSize); 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); memcpy(headerChunk_->payload + pos, og_.header, og_.header_len);
pos += og_.header_len; pos += og_.header_len;
memcpy(headerChunk_->payload + pos, og_.body, og_.body_len); memcpy(headerChunk_->payload + pos, og_.body, og_.body_len);

22
server/publishZeroConf/publishAvahi.cpp
View file

@ -44,7 +44,7 @@ void PublishAvahi::publish(const std::vector<mDNSService>& services)
if (!(simple_poll = avahi_simple_poll_new())) if (!(simple_poll = avahi_simple_poll_new()))
{ {
///TODO: error handling ///TODO: error handling
logE << "Failed to create simple poll object.\n"; LOG(ERROR) << "Failed to create simple poll object.\n";
} }
/// Allocate a new client /// Allocate a new client
@ -54,7 +54,7 @@ void PublishAvahi::publish(const std::vector<mDNSService>& services)
/// Check wether creating the client object succeeded /// Check wether creating the client object succeeded
if (!client_) if (!client_)
{ {
logE << "Failed to create client: " << avahi_strerror(error) << "\n"; LOG(ERROR) << "Failed to create client: " << avahi_strerror(error) << "\n";
} }
active_ = true; active_ = true;
@ -93,7 +93,7 @@ void PublishAvahi::entry_group_callback(AvahiEntryGroup *g, AvahiEntryGroupState
{ {
case AVAHI_ENTRY_GROUP_ESTABLISHED : case AVAHI_ENTRY_GROUP_ESTABLISHED :
/// The entry group has been established successfully /// The entry group has been established successfully
logO << "Service '" << name << "' successfully established.\n"; LOG(INFO) << "Service '" << name << "' successfully established.\n";
break; break;
case AVAHI_ENTRY_GROUP_COLLISION : case AVAHI_ENTRY_GROUP_COLLISION :
@ -105,7 +105,7 @@ void PublishAvahi::entry_group_callback(AvahiEntryGroup *g, AvahiEntryGroupState
avahi_free(name); avahi_free(name);
name = n; 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 /// And recreate the services
static_cast<PublishAvahi*>(userdata)->create_services(avahi_entry_group_get_client(g)); static_cast<PublishAvahi*>(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 : 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 /// Some kind of failure happened while we were registering our services
avahi_simple_poll_quit(simple_poll); 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))) 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; goto fail;
} }
} }
@ -145,7 +145,7 @@ void PublishAvahi::create_services(AvahiClient *c)
int ret; int ret;
if (avahi_entry_group_is_empty(group)) 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 /// We will now add two services and one subtype to the entry group
for (const auto& service: services_) for (const auto& service: services_)
@ -155,7 +155,7 @@ void PublishAvahi::create_services(AvahiClient *c)
if (ret == AVAHI_ERR_COLLISION) if (ret == AVAHI_ERR_COLLISION)
goto 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; goto fail;
} }
} }
@ -170,7 +170,7 @@ void PublishAvahi::create_services(AvahiClient *c)
/// Tell the server to register the service /// Tell the server to register the service
if ((ret = avahi_entry_group_commit(group)) < 0) 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; goto fail;
} }
} }
@ -184,7 +184,7 @@ collision:
avahi_free(name); avahi_free(name);
name = n; 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); avahi_entry_group_reset(group);
@ -211,7 +211,7 @@ void PublishAvahi::client_callback(AvahiClient *c, AvahiClientState state, AVAHI
case AVAHI_CLIENT_FAILURE: 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); avahi_simple_poll_quit(simple_poll);
break; break;

14
server/publishZeroConf/publishBonjour.cpp
View file

@ -90,7 +90,7 @@ void PublishBonjour::worker()
DNSServiceErrorType err = DNSServiceProcessResult(clients[n]); DNSServiceErrorType err = DNSServiceProcessResult(clients[n]);
if (err) if (err)
{ {
logE << "DNSServiceProcessResult returned " << err << "\n"; LOG(ERROR) << "DNSServiceProcessResult returned " << err << "\n";
active_ = false; active_ = false;
} }
} }
@ -100,7 +100,7 @@ void PublishBonjour::worker()
// myTimerCallBack(); // myTimerCallBack();
else if (result < 0) 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) if (errno != EINTR)
active_ = false; active_ = false;
} }
@ -116,23 +116,23 @@ static void DNSSD_API reg_reply(DNSServiceRef sdref, const DNSServiceFlags flags
PublishBonjour* publishBonjour = (PublishBonjour*)context; PublishBonjour* publishBonjour = (PublishBonjour*)context;
(void)publishBonjour; // unused (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 (errorCode == kDNSServiceErr_NoError)
{ {
if (flags & kDNSServiceFlagsAdd) if (flags & kDNSServiceFlagsAdd)
logO << "Name now registered and active\n"; LOG(INFO) << "Name now registered and active\n";
else else
logO << "Name registration removed\n"; LOG(INFO) << "Name registration removed\n";
} }
else if (errorCode == kDNSServiceErr_NameConflict) else if (errorCode == kDNSServiceErr_NameConflict)
{ {
/// TODO: Error handling /// TODO: Error handling
logO << "Name in use, please choose another\n"; LOG(INFO) << "Name in use, please choose another\n";
exit(-1); exit(-1);
} }
else else
logO << "Error " << errorCode << "\n"; LOG(INFO) << "Error " << errorCode << "\n";
if (!(flags & kDNSServiceFlagsMoreComing)) if (!(flags & kDNSServiceFlagsMoreComing))
fflush(stdout); fflush(stdout);

19
server/snapServer.cpp
View file

@ -97,7 +97,7 @@ int main(int argc, char* argv[])
} }
catch (const std::invalid_argument& e) 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"; cout << "\n" << op << "\n";
exit(EXIT_FAILURE); exit(EXIT_FAILURE);
} }
@ -141,7 +141,12 @@ int main(int argc, char* argv[])
return 1; return 1;
} }
std::clog.rdbuf(new Log("snapserver", LOG_DAEMON)); Log::init(
{
make_shared<LogSinkCout>(LogPriority::info, LogSink::Type::all), //, "%Y-%m-%d %H-%M-%S [#prio]"),
make_shared<LogSinkNative>("snapserver", LogPriority::debug, LogSink::Type::special)
}
);
signal(SIGHUP, signal_handler); signal(SIGHUP, signal_handler);
signal(SIGTERM, signal_handler); signal(SIGTERM, signal_handler);
@ -173,7 +178,7 @@ int main(int argc, char* argv[])
processPriority = 19; processPriority = 19;
if (processPriority != 0) if (processPriority != 0)
setpriority(PRIO_PROCESS, 0, processPriority); setpriority(PRIO_PROCESS, 0, processPriority);
logS(kLogNotice) << "daemon started" << std::endl; SLOG(LOG_NOTICE) << "daemon started" << std::endl;
} }
#endif #endif
@ -201,17 +206,17 @@ int main(int argc, char* argv[])
io_service.stop(); io_service.stop();
t.join(); t.join();
logO << "Stopping streamServer" << endl; LOG(INFO) << "Stopping streamServer" << endl;
streamServer->stop(); streamServer->stop();
logO << "done" << endl; LOG(INFO) << "done" << endl;
} }
catch (const std::exception& e) catch (const std::exception& e)
{ {
logS(kLogErr) << "Exception: " << e.what() << std::endl; SLOG(LOG_ERR) << "Exception: " << e.what() << std::endl;
exitcode = EXIT_FAILURE; exitcode = EXIT_FAILURE;
} }
logS(kLogNotice) << "daemon terminated." << endl; SLOG(LOG_NOTICE) << "daemon terminated." << endl;
exit(exitcode); exit(exitcode);
} }

42
server/streamServer.cpp
View file

@ -41,8 +41,8 @@ StreamServer::~StreamServer()
void StreamServer::onStateChanged(const PcmStream* pcmStream, const ReaderState& state) 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"}}}} /// 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"; LOG(INFO) << "onStateChanged (" << pcmStream->getName() << "): " << state << "\n";
// logO << pcmStream->toJson().dump(4); // LOG(INFO) << pcmStream->toJson().dump(4);
json notification = jsonrpcpp::Notification("Stream.OnUpdate", jsonrpcpp::Parameter("id", pcmStream->getId(), "stream", pcmStream->toJson())).to_json(); json notification = jsonrpcpp::Notification("Stream.OnUpdate", jsonrpcpp::Parameter("id", pcmStream->getId(), "stream", pcmStream->toJson())).to_json();
controlServer_->send(notification.dump(), NULL); controlServer_->send(notification.dump(), NULL);
////cout << "Notification: " << notification.dump() << "\n"; ////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) 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()); bool isDefaultStream(pcmStream == streamManager_->getDefaultStream().get());
std::shared_ptr<const msg::BaseMessage> shared_message(chunk); std::shared_ptr<const msg::BaseMessage> shared_message(chunk);
@ -82,7 +82,7 @@ void StreamServer::onChunkRead(const PcmStream* pcmStream, const msg::PcmChunk*
void StreamServer::onResync(const PcmStream* pcmStream, double ms) 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) if (session == nullptr)
return; return;
logO << "onDisconnect: " << session->clientId << "\n"; LOG(INFO) << "onDisconnect: " << session->clientId << "\n";
logD << "sessions: " << sessions_.size() << "\n"; LOG(DEBUG) << "sessions: " << sessions_.size() << "\n";
// don't block: remove StreamSession in a thread // don't block: remove StreamSession in a thread
auto func = [](shared_ptr<StreamSession> s)->void{s->stop();}; auto func = [](shared_ptr<StreamSession> s)->void{s->stop();};
std::thread t(func, session); std::thread t(func, session);
t.detach(); t.detach();
sessions_.erase(session); sessions_.erase(session);
logD << "sessions: " << sessions_.size() << "\n"; LOG(DEBUG) << "sessions: " << sessions_.size() << "\n";
// notify controllers if not yet done // notify controllers if not yet done
ClientInfoPtr clientInfo = Config::instance().getClientInfo(streamSession->clientId); ClientInfoPtr clientInfo = Config::instance().getClientInfo(streamSession->clientId);
@ -126,7 +126,7 @@ void StreamServer::ProcessRequest(const jsonrpcpp::request_ptr request, jsonrpcp
{ {
try try
{ {
////logO << "StreamServer::ProcessRequest method: " << request->method << ", " << "id: " << request->id << "\n"; ////LOG(INFO) << "StreamServer::ProcessRequest method: " << request->method << ", " << "id: " << request->id << "\n";
Json result; Json result;
if (request->method.find("Client.") == 0) if (request->method.find("Client.") == 0)
@ -366,12 +366,12 @@ void StreamServer::ProcessRequest(const jsonrpcpp::request_ptr request, jsonrpcp
} }
catch (const jsonrpcpp::RequestException& e) 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)); response.reset(new jsonrpcpp::RequestException(e));
} }
catch (const exception& 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)); 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) void StreamServer::onMessageReceived(ControlSession* controlSession, const std::string& message)
{ {
logD << "onMessageReceived: " << message << "\n"; LOG(DEBUG) << "onMessageReceived: " << message << "\n";
jsonrpcpp::entity_ptr entity(nullptr); jsonrpcpp::entity_ptr entity(nullptr);
try try
{ {
@ -445,14 +445,14 @@ void StreamServer::onMessageReceived(ControlSession* controlSession, const std::
void StreamServer::onMessageReceived(StreamSession* connection, const msg::BaseMessage& baseMessage, char* buffer) 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) if (baseMessage.type == message_type::kTime)
{ {
msg::Time* timeMsg = new msg::Time(); msg::Time* timeMsg = new msg::Time();
timeMsg->deserialize(baseMessage, buffer); timeMsg->deserialize(baseMessage, buffer);
timeMsg->refersTo = timeMsg->id; timeMsg->refersTo = timeMsg->id;
timeMsg->latency = timeMsg->received - timeMsg->sent; 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); connection->sendAsync(timeMsg, true);
// refresh connection state // refresh connection state
@ -468,11 +468,11 @@ void StreamServer::onMessageReceived(StreamSession* connection, const msg::BaseM
msg::Hello helloMsg; msg::Hello helloMsg;
helloMsg.deserialize(baseMessage, buffer); helloMsg.deserialize(baseMessage, buffer);
connection->clientId = helloMsg.getUniqueId(); 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() << ", ClientName: " << helloMsg.getClientName() << ", OS: " << helloMsg.getOS() << ", Arch: " << helloMsg.getArch()
<< ", Protocol version: " << helloMsg.getProtocolVersion() << "\n"; << ", Protocol version: " << helloMsg.getProtocolVersion() << "\n";
logD << "request kServerSettings: " << connection->clientId << "\n"; LOG(DEBUG) << "request kServerSettings: " << connection->clientId << "\n";
// std::lock_guard<std::mutex> mlock(mutex_); // std::lock_guard<std::mutex> mlock(mutex_);
bool newGroup(false); bool newGroup(false);
GroupPtr group = Config::instance().getGroupFromClient(connection->clientId); 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); ClientInfoPtr client = group->getClient(connection->clientId);
logD << "request kServerSettings\n"; LOG(DEBUG) << "request kServerSettings\n";
msg::ServerSettings* serverSettings = new msg::ServerSettings(); msg::ServerSettings* serverSettings = new msg::ServerSettings();
serverSettings->setVolume(client->config.volume.percent); serverSettings->setVolume(client->config.volume.percent);
serverSettings->setMuted(client->config.volume.muted || group->muted); serverSettings->setMuted(client->config.volume.muted || group->muted);
@ -512,7 +512,7 @@ void StreamServer::onMessageReceived(StreamSession* connection, const msg::BaseM
stream = streamManager_->getDefaultStream(); stream = streamManager_->getDefaultStream();
group->streamId = stream->getId(); group->streamId = stream->getId();
} }
logO << "Group: " << group->id << ", stream: " << group->streamId << "\n"; LOG(DEBUG) << "Group: " << group->id << ", stream: " << group->streamId << "\n";
Config::instance().save(); Config::instance().save();
@ -556,7 +556,7 @@ session_ptr StreamServer::getStreamSession(StreamSession* streamSession) const
session_ptr StreamServer::getStreamSession(const std::string& clientId) const session_ptr StreamServer::getStreamSession(const std::string& clientId) const
{ {
// logO << "getStreamSession: " << mac << "\n"; // LOG(INFO) << "getStreamSession: " << mac << "\n";
std::lock_guard<std::recursive_mutex> mlock(sessionsMutex_); std::lock_guard<std::recursive_mutex> mlock(sessionsMutex_);
for (auto session: sessions_) for (auto session: sessions_)
{ {
@ -585,7 +585,7 @@ void StreamServer::handleAccept(socket_ptr socket)
/// experimental: turn on tcp::no_delay /// experimental: turn on tcp::no_delay
socket->set_option(tcp::no_delay(true)); 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<StreamSession> session = make_shared<StreamSession>(this, socket); shared_ptr<StreamSession> session = make_shared<StreamSession>(this, socket);
session->setBufferMs(settings_.bufferMs); session->setBufferMs(settings_.bufferMs);
@ -611,7 +611,7 @@ void StreamServer::start()
{ {
PcmStreamPtr stream = streamManager_->addStream(streamUri); PcmStreamPtr stream = streamManager_->addStream(streamUri);
if (stream) if (stream)
logO << "Stream: " << stream->getUri().toJson() << "\n"; LOG(INFO) << "Stream: " << stream->getUri().toJson() << "\n";
} }
streamManager_->start(); streamManager_->start();
@ -620,7 +620,7 @@ void StreamServer::start()
} }
catch (const std::exception& e) catch (const std::exception& e)
{ {
logS(kLogNotice) << "StreamServer::start: " << e.what() << endl; SLOG(LOG_NOTICE) << "StreamServer::start: " << e.what() << endl;
stop(); stop();
throw; throw;
} }

24
server/streamSession.cpp
View file

@ -80,18 +80,18 @@ void StreamSession::stop()
{ {
std::lock_guard<std::mutex> socketLock(socketMutex_); std::lock_guard<std::mutex> socketLock(socketMutex_);
socket_->shutdown(asio::ip::tcp::socket::shutdown_both, ec); 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); 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()) if (readerThread_ && readerThread_->joinable())
{ {
logD << "joining readerThread\n"; LOG(DEBUG) << "joining readerThread\n";
readerThread_->join(); readerThread_->join();
} }
if (writerThread_ && writerThread_->joinable()) if (writerThread_ && writerThread_->joinable())
{ {
logD << "joining writerThread\n"; LOG(DEBUG) << "joining writerThread\n";
messages_.abort_wait(); messages_.abort_wait();
writerThread_->join(); writerThread_->join();
} }
@ -103,7 +103,7 @@ void StreamSession::stop()
readerThread_ = nullptr; readerThread_ = nullptr;
writerThread_ = nullptr; writerThread_ = nullptr;
socket_ = 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 bool StreamSession::send(const msg::BaseMessage* message) const
{ {
//TODO on exception: set active = false //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<std::mutex> socketLock(socketMutex_); std::lock_guard<std::mutex> socketLock(socketMutex_);
{ {
std::lock_guard<std::mutex> activeLock(activeMutex_); std::lock_guard<std::mutex> activeLock(activeMutex_);
@ -169,7 +169,7 @@ bool StreamSession::send(const msg::BaseMessage* message) const
message->sent = t; message->sent = t;
message->serialize(stream); message->serialize(stream);
asio::write(*socket_.get(), streambuf); 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; return true;
} }
@ -183,11 +183,11 @@ void StreamSession::getNextMessage()
baseMessage.deserialize(&buffer[0]); baseMessage.deserialize(&buffer[0]);
if (baseMessage.size > msg::max_size) 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(); stop();
return; 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()) if (baseMessage.size > buffer.size())
buffer.resize(baseMessage.size); buffer.resize(baseMessage.size);
// { // {
@ -213,7 +213,7 @@ void StreamSession::reader()
} }
catch (const std::exception& e) 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)) if (active_ && (messageReceiver_ != NULL))
@ -241,7 +241,7 @@ void StreamSession::writer()
size_t age = 0; size_t age = 0;
if (now > wireChunk->start()) if (now > wireChunk->start())
age = std::chrono::duration_cast<chronos::msec>(now - wireChunk->start()).count(); age = std::chrono::duration_cast<chronos::msec>(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_) if (age > bufferMs_)
continue; continue;
} }
@ -252,7 +252,7 @@ void StreamSession::writer()
} }
catch (const std::exception& e) 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)) if (active_ && (messageReceiver_ != NULL))

8
server/streamreader/airplayStream.cpp
View file

@ -72,17 +72,17 @@ void AirplayStream::onStderrMsg(const char* buffer, size_t n)
string logmsg = utils::string::trim_copy(string(buffer, n)); string logmsg = utils::string::trim_copy(string(buffer, n));
if (logmsg.empty()) if (logmsg.empty())
return; return;
logO << "(" << getName() << ") " << logmsg << "\n"; LOG(INFO) << "(" << getName() << ") " << logmsg << "\n";
if (logmsg.find("Is another Shairport Sync running on this device") != string::npos) 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_; ++port_;
params_ = params_wo_port_ + " --port=" + cpt::to_string(port_); params_ = params_wo_port_ + " --port=" + cpt::to_string(port_);
} }
else if (logmsg.find("Invalid audio output specified") != string::npos) else if (logmsg.find("Invalid audio output specified") != string::npos)
{ {
logE << "shairport sync compiled without stdout audio backend\n"; LOG(ERROR) << "shairport sync compiled without stdout audio backend\n";
logE << "build with: \"./configure --with-stdout --with-avahi --with-ssl=openssl --with-metadata\"\n"; LOG(ERROR) << "build with: \"./configure --with-stdout --with-avahi --with-ssl=openssl --with-metadata\"\n";
} }
} }

6
server/streamreader/fileStream.cpp
View file

@ -36,7 +36,7 @@ FileStream::FileStream(PcmListener* pcmListener, const StreamUri& uri) : PcmStre
ifs.open(uri_.path.c_str(), std::ifstream::in|std::ifstream::binary); ifs.open(uri_.path.c_str(), std::ifstream::in|std::ifstream::binary);
if (!ifs.good()) 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 + "\""); throw SnapException("failed to open PCM file: \"" + uri_.path + "\"");
} }
} }
@ -91,7 +91,7 @@ void FileStream::worker()
if (nextTick >= currentTick) if (nextTick >= currentTick)
{ {
// logO << "sleep: " << nextTick - currentTick << "\n"; // LOG(INFO) << "sleep: " << nextTick - currentTick << "\n";
if (!sleep(nextTick - currentTick)) if (!sleep(nextTick - currentTick))
break; break;
} }
@ -106,7 +106,7 @@ void FileStream::worker()
} }
catch(const std::exception& e) catch(const std::exception& e)
{ {
logE << "(FileStream) Exception: " << e.what() << std::endl; LOG(ERROR) << "(FileStream) Exception: " << e.what() << std::endl;
} }
} }
} }

6
server/streamreader/pcmStream.cpp
View file

@ -46,7 +46,7 @@ PcmStream::PcmStream(PcmListener* pcmListener, const StreamUri& uri) :
if (uri_.query.find("sampleformat") == uri_.query.end()) if (uri_.query.find("sampleformat") == uri_.query.end())
throw SnapException("Stream URI must have a sampleformat"); throw SnapException("Stream URI must have a sampleformat");
sampleFormat_ = SampleFormat(uri_.query["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()) if (uri_.query.find("buffer_ms") != uri_.query.end())
pcmReadMs_ = cpt::stoul(uri_.query["buffer_ms"]); pcmReadMs_ = cpt::stoul(uri_.query["buffer_ms"]);
@ -91,7 +91,7 @@ const SampleFormat& PcmStream::getSampleFormat() const
void PcmStream::start() void PcmStream::start()
{ {
logD << "PcmStream start: " << sampleFormat_.getFormat() << "\n"; LOG(DEBUG) << "PcmStream start: " << sampleFormat_.getFormat() << "\n";
encoder_->init(this, sampleFormat_); encoder_->init(this, sampleFormat_);
active_ = true; active_ = true;
thread_ = thread(&PcmStream::worker, this); 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) 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) if (duration <= 0)
return; return;

4
server/streamreader/pipeStream.cpp
View file

@ -39,7 +39,7 @@ PipeStream::PipeStream(PcmListener* pcmListener, const StreamUri& uri) : PcmStre
umask(0); umask(0);
string mode = uri_.getQuery("mode", "create"); string mode = uri_.getQuery("mode", "create");
logO << "PipeStream mode: " << mode << "\n"; LOG(INFO) << "PipeStream mode: " << mode << "\n";
if ((mode != "read") && (mode != "create")) if ((mode != "read") && (mode != "create"))
throw SnapException("create mode for fifo must be \"read\" or \"create\""); throw SnapException("create mode for fifo must be \"read\" or \"create\"");
@ -130,7 +130,7 @@ void PipeStream::worker()
{ {
if (lastException != e.what()) if (lastException != e.what())
{ {
logE << "(PipeStream) Exception: " << e.what() << std::endl; LOG(ERROR) << "(PipeStream) Exception: " << e.what() << std::endl;
lastException = e.what(); lastException = e.what();
} }
if (!sleep(100)) if (!sleep(100))

4
server/streamreader/processStream.cpp
View file

@ -123,7 +123,7 @@ void ProcessStream::onStderrMsg(const char* buffer, size_t n)
{ {
string line = utils::string::trim_copy(string(buffer, n)); string line = utils::string::trim_copy(string(buffer, n));
if ((line.find('\0') == string::npos) && !line.empty()) 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()) if (lastException != e.what())
{ {
logE << "(PipeStream) Exception: " << e.what() << std::endl; LOG(ERROR) << "(PipeStream) Exception: " << e.what() << std::endl;
lastException = e.what(); lastException = e.what();
} }
process_->kill(); process_->kill();

6
server/streamreader/spotifyStream.cpp
View file

@ -51,7 +51,7 @@ SpotifyStream::SpotifyStream(PcmListener* pcmListener, const StreamUri& uri) : P
params_ += " --onstart \"" + onstart + "\""; params_ += " --onstart \"" + onstart + "\"";
if (!onstop.empty()) if (!onstop.empty())
params_ += " --onstop \"" + onstop + "\""; 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.find('\0') == string::npos) &&
(logmsg.size() > 4)) (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) void SpotifyStream::onTimeout(const Watchdog* watchdog, size_t ms)
{ {
logE << "Spotify timeout: " << ms / 1000 << "\n"; LOG(ERROR) << "Spotify timeout: " << ms / 1000 << "\n";
if (process_) if (process_)
process_->kill(); process_->kill();
} }

4
server/streamreader/streamManager.cpp
View file

@ -49,11 +49,11 @@ PcmStreamPtr StreamManager::addStream(const std::string& uri)
if (streamUri.query.find("buffer_ms") == streamUri.query.end()) if (streamUri.query.find("buffer_ms") == streamUri.query.end())
streamUri.query["buffer_ms"] = cpt::to_string(readBufferMs_); 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"; // << streamUri.host << "\npath: " << streamUri.path << "\nfragment: " << streamUri.fragment << "\n";
// for (auto kv: streamUri.query) // 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); PcmStreamPtr stream(nullptr);
if (streamUri.scheme == "pipe") if (streamUri.scheme == "pipe")

12
server/streamreader/streamUri.cpp
View file

@ -31,7 +31,7 @@ StreamUri::StreamUri(const std::string& streamUri)
// https://en.wikipedia.org/wiki/Uniform_Resource_Identifier // https://en.wikipedia.org/wiki/Uniform_Resource_Identifier
// scheme:[//[user:password@]host[:port]][/]path[?query][#fragment] // 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 :( // 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; size_t pos;
uri = strutils::trim_copy(streamUri); uri = strutils::trim_copy(streamUri);
while (!uri.empty() && ((uri[0] == '\'') || (uri[0] == '"'))) 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); uri = uri.substr(0, this->uri.length()-1);
string decodedUri = strutils::uriDecode(uri); string decodedUri = strutils::uriDecode(uri);
logD << "StreamUri: " << decodedUri << "\n"; LOG(DEBUG) << "StreamUri: " << decodedUri << "\n";
string tmp(decodedUri); string tmp(decodedUri);
@ -49,7 +49,7 @@ StreamUri::StreamUri(const std::string& streamUri)
throw invalid_argument("missing ':'"); throw invalid_argument("missing ':'");
scheme = strutils::trim_copy(tmp.substr(0, pos)); scheme = strutils::trim_copy(tmp.substr(0, pos));
tmp = tmp.substr(pos + 1); tmp = tmp.substr(pos + 1);
logD << "scheme: '" << scheme << "' tmp: '" << tmp << "'\n"; LOG(DEBUG) << "scheme: '" << scheme << "' tmp: '" << tmp << "'\n";
if (tmp.find("//") != 0) if (tmp.find("//") != 0)
throw invalid_argument("missing host separator: '//'"); throw invalid_argument("missing host separator: '//'");
@ -61,7 +61,7 @@ StreamUri::StreamUri(const std::string& streamUri)
host = strutils::trim_copy(tmp.substr(0, pos)); host = strutils::trim_copy(tmp.substr(0, pos));
tmp = tmp.substr(pos); tmp = tmp.substr(pos);
path = tmp; path = tmp;
logD << "host: '" << host << "' tmp: '" << tmp << "' path: '" << path << "'\n"; LOG(DEBUG) << "host: '" << host << "' tmp: '" << tmp << "' path: '" << path << "'\n";
pos = tmp.find('?'); pos = tmp.find('?');
if (pos == string::npos) if (pos == string::npos)
@ -70,7 +70,7 @@ StreamUri::StreamUri(const std::string& streamUri)
path = strutils::trim_copy(tmp.substr(0, pos)); path = strutils::trim_copy(tmp.substr(0, pos));
tmp = tmp.substr(pos + 1); tmp = tmp.substr(pos + 1);
string queryStr = tmp; string queryStr = tmp;
logD << "path: '" << path << "' tmp: '" << tmp << "' query: '" << queryStr << "'\n"; LOG(DEBUG) << "path: '" << path << "' tmp: '" << tmp << "' query: '" << queryStr << "'\n";
pos = tmp.find('#'); pos = tmp.find('#');
if (pos != string::npos) if (pos != string::npos)
@ -78,7 +78,7 @@ StreamUri::StreamUri(const std::string& streamUri)
queryStr = tmp.substr(0, pos); queryStr = tmp.substr(0, pos);
tmp = tmp.substr(pos + 1); tmp = tmp.substr(pos + 1);
fragment = strutils::trim_copy(tmp); fragment = strutils::trim_copy(tmp);
logD << "query: '" << queryStr << "' fragment: '" << fragment << "' tmp: '" << tmp << "'\n"; LOG(DEBUG) << "query: '" << queryStr << "' fragment: '" << fragment << "' tmp: '" << tmp << "'\n";
} }
vector<string> keyValueList = strutils::split(queryStr, '&'); vector<string> keyValueList = strutils::split(queryStr, '&');