# HG changeset patch
# User František Kučera <franta-hg@frantovo.cz>
# Date 1609776717 -3600
# Node ID 334b727f7516a5d4f95252f2fcb0b86d5153f997
# Parent  15d87fdd6e6cf2cebcaf6f1ca893109e4c7dea1f
improved logging and error messages

diff -r 15d87fdd6e6c -r 334b727f7516 AlsaBridge.cpp
--- a/AlsaBridge.cpp	Mon Jan 04 15:45:12 2021 +0100
+++ b/AlsaBridge.cpp	Mon Jan 04 17:11:57 2021 +0100
@@ -15,6 +15,7 @@
  * along with this program. If not, see <http://www.gnu.org/licenses/>.
  */
 #include <iostream>
+#include <iomanip>
 #include <sstream>
 #include <stdexcept>
 #include <thread>
@@ -75,6 +76,12 @@
 		}
 	}
 
+	std::string toString(const MidiMessage& midiMessage) {
+		std::stringstream result;
+		for (uint8_t b : midiMessage) result << std::hex << std::setw(2) << std::setfill('0') << (int) b;
+		return result.str();
+	}
+
 	void run() {
 		while (!stopped) {
 			{
@@ -93,12 +100,12 @@
 public:
 
 	AlsaBridgeImpl(djmfix::DJMFix* djmFix, const std::string& cardNamePattern, djmfix::logging::Logger* logger) : djmFix(djmFix), logger(logger ? logger : djmfix::logging::blackhole()) {
-		if (djmFix == nullptr) throw std::invalid_argument("need a djmFix for AlsaBridge");
+		if (djmFix == nullptr) throw std::invalid_argument("Need a djmFix for AlsaBridge.");
 
 		std::string deviceName = findDeviceName(std::regex(cardNamePattern));
 
 		int error = snd_rawmidi_open(&input, &output, deviceName.c_str(), SND_RAWMIDI_NONBLOCK);
-		if (error) throw std::invalid_argument("unable to open ALSA device");
+		if (error) throw std::invalid_argument("Unable to open ALSA device.");
 
 
 		djmFix->setMidiSender(this);
@@ -108,7 +115,7 @@
 		// TODO: do not use raw/exclusive access to the MIDI device
 		snd_rawmidi_close(input);
 		snd_rawmidi_close(output);
-		logger->log(L::FINE, "~AlsaBridgeImpl()");
+		logger->log(L::FINER, "~AlsaBridgeImpl()");
 	}
 
 	virtual void start() override {
@@ -125,7 +132,7 @@
 	virtual void send(MidiMessage midiMessage) override {
 		std::lock_guard<std::recursive_mutex> lock(midiMutex);
 		ssize_t length = snd_rawmidi_write(output, midiMessage.data(), midiMessage.size());
-		logger->log(L::INFO, "AlsaBridgeImpl::send(): length = " + std::to_string(length));
+		logger->log(L::FINE, "Sent message: length = " + std::to_string(length) + " data = " + toString(midiMessage));
 	}
 
 };
diff -r 15d87fdd6e6c -r 334b727f7516 DJMFix.cpp
--- a/DJMFix.cpp	Mon Jan 04 15:45:12 2021 +0100
+++ b/DJMFix.cpp	Mon Jan 04 17:11:57 2021 +0100
@@ -35,6 +35,8 @@
 private:
 	MidiSender* midiSender;
 	djmfix::logging::Logger* logger;
+	const int keepAliveInterval = 200;
+	int keepAliveCounter = 0;
 	std::thread keepAliveThread;
 	std::recursive_mutex midiMutex;
 	std::atomic<bool> running{false};
@@ -46,7 +48,9 @@
 		while (!stopped) {
 			logger->log(L::FINE, "DJMFixImpl::run()");
 			if (sendKeepAlive) send({0xf0, 0x00, 0x40, 0x05, 0x00, 0x00, 0x00, 0x17, 0x00, 0x50, 0x01, 0xf7});
-			std::this_thread::sleep_for(std::chrono::milliseconds(200));
+			std::this_thread::sleep_for(std::chrono::milliseconds(keepAliveInterval));
+			keepAliveCounter++;
+			if (keepAliveCounter % (60 * 1000 / keepAliveInterval) == 0) logger->log(L::INFO, "Still sending periodic keep-alive messages (each " + std::to_string(keepAliveInterval) + " ms).");
 		}
 	}
 
@@ -62,7 +66,7 @@
 	}
 
 	Bytes normalize(const Bytes& data) {
-		if (data.size() % 2) throw std::invalid_argument("data before normalization must have even number of bytes");
+		if (data.size() % 2) throw std::invalid_argument("Data before normalization must have even number of bytes.");
 		Bytes result;
 		result.reserve(data.size() / 2);
 		for (size_t i = 0; i < data.size() / 2; i++) result.push_back((data[i * 2] & 0x0F) << 4 | (data[i * 2 + 1] & 0x0F));
@@ -111,7 +115,7 @@
 	}
 
 	template<typename T> std::vector<T> xOR(const std::vector<T>& a, const std::vector<T>& b) {
-		if (a.size() != b.size()) throw std::invalid_argument("xor: both must be the same length");
+		if (a.size() != b.size()) throw std::invalid_argument("Both must be the same length when doing XOR.");
 		std::vector<T> result;
 		result.reserve(a.size());
 		for (size_t i = 0; i < a.size(); i++) result.push_back(a[i] ^ b[i]);
@@ -124,28 +128,30 @@
 	}
 
 	virtual ~DJMFixImpl() override {
-		logger->log(L::FINE, "~DJMFixImpl()");
+		logger->log(L::FINER, "~DJMFixImpl()");
 		if (running) stop();
 	}
 
 	void setMidiSender(MidiSender* midiSender) {
-		logger->log(L::FINE, "DJMFixImpl::setMidiSender()");
+		logger->log(L::FINER, "DJMFixImpl::setMidiSender()");
 		this->midiSender = midiSender;
 	}
 
 	virtual void receive(const MidiMessage& midiMessage) override {
-		logger->log(L::INFO, "received message: size = " + std::to_string(midiMessage.size()) + " data = " + toString(midiMessage));
+		logger->log(L::FINE, "Received a message: size = " + std::to_string(midiMessage.size()) + " data = " + toString(midiMessage));
 		std::lock_guard<std::recursive_mutex> lock(midiMutex);
 
 
 		if (midiMessage.size() == 12 && midiMessage[9] == 0x11) {
+			logger->log(L::INFO, "Received greeting message.");
 			send({0xf0, 0x00, 0x40, 0x05, 0x00, 0x00, 0x00, 0x17, 0x00, 0x12, 0x2a, 0x01, 0x0b, 0x50, 0x69, 0x6f, 0x6e, 0x65, 0x65, 0x72, 0x44, 0x4a, 0x02, 0x0b, 0x72, 0x65, 0x6b, 0x6f, 0x72, 0x64, 0x62, 0x6f, 0x78, 0x03, 0x12, 0x02, 0x09, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x02, 0x03, 0x04, 0x08, 0x00, 0x00, 0x00, 0x00, 0xf7});
+			logger->log(L::INFO, "Sent message with seed1.");
 		} else if (midiMessage.size() == 54 && midiMessage[9] == 0x13 && midiMessage[33] == 0x04 && midiMessage[43] == 0x03) {
 			Bytes hash1(midiMessage.begin() + 35, midiMessage.begin() + 35 + 8);
 			seed2 = Bytes(midiMessage.begin() + 45, midiMessage.begin() + 45 + 8);
 			hash1 = normalize(hash1);
 			seed2 = normalize(seed2);
-			logger->log(L::INFO, "got message with hash1 = " + toString(hash1) + " and seed2 = " + toString(seed2));
+			logger->log(L::INFO, "Received message with hash1 = " + toString(hash1) + " and seed2 = " + toString(seed2));
 
 			Bytes seed0 = {0x68, 0x01, 0x31, 0xFB};
 			Bytes seed1 = {0x29, 0x00, 0x00, 0x00, 0x23, 0x48, 0x00, 0x00};
@@ -153,13 +159,14 @@
 			Bytes hash1check = toBytes(fnv32hash(concat(seed1, xOR(seed0, seed2))));
 
 			if (equals(hash1, hash1check)) {
-				logger->log(L::INFO, "hash1 verification: OK");
+				logger->log(L::INFO, "Verification of hash1 was successful.");
 				Bytes hash2 = toBytes(fnv32hash(concat(seed2, xOR(seed0, seed2))));
 				send(concat({0xf0, 0x00, 0x40, 0x05, 0x00, 0x00, 0x00, 0x17, 0x00, 0x14, 0x38, 0x01, 0x0b, 0x50, 0x69, 0x6f, 0x6e, 0x65, 0x65, 0x72, 0x44, 0x4a, 0x02, 0x0b, 0x72, 0x65, 0x6b, 0x6f, 0x72, 0x64, 0x62, 0x6f, 0x78, 0x04, 0x0a}, concat(denormalize(hash2),{0x05, 0x16, 0x05, 0x09, 0x0b, 0x05, 0x04, 0x0b, 0x0f, 0x0e, 0x0e, 0x04, 0x04, 0x0a, 0x05, 0x0a, 0x0c, 0x08, 0x0e, 0x04, 0x0c, 0x05, 0xf7})));
+				logger->log(L::INFO, "Sent message with hash2.");
 			} else {
 				std::stringstream logMessage;
 				logMessage
-						<< "hash1 verification failed: "
+						<< "Verification of hash1 failed: "
 						<< " midiMessage = " << toString(midiMessage)
 						<< " seed0 = " << toString(seed0)
 						<< " seed1 = " << toString(seed1)
@@ -171,16 +178,18 @@
 			}
 		} else if (midiMessage.size() == 12 && midiMessage[9] == 0x15) {
 			sendKeepAlive = true;
+			logger->log(L::INFO, "Received acknowledgment message. Started sending keep-alive messages. LINE/PHONO channels should work now.");
 		}
 
 	}
 
 	void start() override {
 		logger->log(L::FINE, "DJMFixImpl::start()");
-		if (midiSender == nullptr) throw std::logic_error("need a midiSender when starting DJMFix");
+		if (midiSender == nullptr) throw std::logic_error("Need a midiSender when starting DJMFix");
 
 		// TODO: methods for parsing and constructing messages from parts (TLV)
 		send({0xf0, 0x00, 0x40, 0x05, 0x00, 0x00, 0x00, 0x17, 0x00, 0x50, 0x01, 0xf7});
+		logger->log(L::INFO, "Sent greeting message.");
 
 		keepAliveThread = std::thread(&DJMFixImpl::run, this);
 		running = true;
diff -r 15d87fdd6e6c -r 334b727f7516 djm-fix.cpp
--- a/djm-fix.cpp	Mon Jan 04 15:45:12 2021 +0100
+++ b/djm-fix.cpp	Mon Jan 04 17:11:57 2021 +0100
@@ -83,7 +83,7 @@
 	using L = djmfix::logging::Level;
 	std::unique_ptr<djmfix::logging::Logger> logger(djmfix::logging::create(std::cerr, L::INFO));
 	try {
-		logger->log(L::INFO, "djm-fix started");
+		logger->log(L::INFO, "DJM-Fix started.");
 		std::string cardNamePattern = argc == 2 ? argv[1] : "Pioneer DJ.*";
 
 		signal(SIGINT, interrupt);
@@ -94,7 +94,7 @@
 		while (run) std::this_thread::sleep_for(std::chrono::milliseconds(100));
 		
 		std::cerr << std::endl;
-		logger->log(L::INFO, "djm-fix stopping");
+		logger->log(L::INFO, "DJM-Fix stopping.");
 		
 		alsaBridge->stop();