improved logging and error messages v_0 tip
authorFrantišek Kučera <franta-hg@frantovo.cz>
Mon, 04 Jan 2021 17:11:57 +0100
branchv_0
changeset 13334b727f7516
parent 12 15d87fdd6e6c
improved logging and error messages
AlsaBridge.cpp
DJMFix.cpp
djm-fix.cpp
     1.1 --- a/AlsaBridge.cpp	Mon Jan 04 15:45:12 2021 +0100
     1.2 +++ b/AlsaBridge.cpp	Mon Jan 04 17:11:57 2021 +0100
     1.3 @@ -15,6 +15,7 @@
     1.4   * along with this program. If not, see <http://www.gnu.org/licenses/>.
     1.5   */
     1.6  #include <iostream>
     1.7 +#include <iomanip>
     1.8  #include <sstream>
     1.9  #include <stdexcept>
    1.10  #include <thread>
    1.11 @@ -75,6 +76,12 @@
    1.12  		}
    1.13  	}
    1.14  
    1.15 +	std::string toString(const MidiMessage& midiMessage) {
    1.16 +		std::stringstream result;
    1.17 +		for (uint8_t b : midiMessage) result << std::hex << std::setw(2) << std::setfill('0') << (int) b;
    1.18 +		return result.str();
    1.19 +	}
    1.20 +
    1.21  	void run() {
    1.22  		while (!stopped) {
    1.23  			{
    1.24 @@ -93,12 +100,12 @@
    1.25  public:
    1.26  
    1.27  	AlsaBridgeImpl(djmfix::DJMFix* djmFix, const std::string& cardNamePattern, djmfix::logging::Logger* logger) : djmFix(djmFix), logger(logger ? logger : djmfix::logging::blackhole()) {
    1.28 -		if (djmFix == nullptr) throw std::invalid_argument("need a djmFix for AlsaBridge");
    1.29 +		if (djmFix == nullptr) throw std::invalid_argument("Need a djmFix for AlsaBridge.");
    1.30  
    1.31  		std::string deviceName = findDeviceName(std::regex(cardNamePattern));
    1.32  
    1.33  		int error = snd_rawmidi_open(&input, &output, deviceName.c_str(), SND_RAWMIDI_NONBLOCK);
    1.34 -		if (error) throw std::invalid_argument("unable to open ALSA device");
    1.35 +		if (error) throw std::invalid_argument("Unable to open ALSA device.");
    1.36  
    1.37  
    1.38  		djmFix->setMidiSender(this);
    1.39 @@ -108,7 +115,7 @@
    1.40  		// TODO: do not use raw/exclusive access to the MIDI device
    1.41  		snd_rawmidi_close(input);
    1.42  		snd_rawmidi_close(output);
    1.43 -		logger->log(L::FINE, "~AlsaBridgeImpl()");
    1.44 +		logger->log(L::FINER, "~AlsaBridgeImpl()");
    1.45  	}
    1.46  
    1.47  	virtual void start() override {
    1.48 @@ -125,7 +132,7 @@
    1.49  	virtual void send(MidiMessage midiMessage) override {
    1.50  		std::lock_guard<std::recursive_mutex> lock(midiMutex);
    1.51  		ssize_t length = snd_rawmidi_write(output, midiMessage.data(), midiMessage.size());
    1.52 -		logger->log(L::INFO, "AlsaBridgeImpl::send(): length = " + std::to_string(length));
    1.53 +		logger->log(L::FINE, "Sent message: length = " + std::to_string(length) + " data = " + toString(midiMessage));
    1.54  	}
    1.55  
    1.56  };
     2.1 --- a/DJMFix.cpp	Mon Jan 04 15:45:12 2021 +0100
     2.2 +++ b/DJMFix.cpp	Mon Jan 04 17:11:57 2021 +0100
     2.3 @@ -35,6 +35,8 @@
     2.4  private:
     2.5  	MidiSender* midiSender;
     2.6  	djmfix::logging::Logger* logger;
     2.7 +	const int keepAliveInterval = 200;
     2.8 +	int keepAliveCounter = 0;
     2.9  	std::thread keepAliveThread;
    2.10  	std::recursive_mutex midiMutex;
    2.11  	std::atomic<bool> running{false};
    2.12 @@ -46,7 +48,9 @@
    2.13  		while (!stopped) {
    2.14  			logger->log(L::FINE, "DJMFixImpl::run()");
    2.15  			if (sendKeepAlive) send({0xf0, 0x00, 0x40, 0x05, 0x00, 0x00, 0x00, 0x17, 0x00, 0x50, 0x01, 0xf7});
    2.16 -			std::this_thread::sleep_for(std::chrono::milliseconds(200));
    2.17 +			std::this_thread::sleep_for(std::chrono::milliseconds(keepAliveInterval));
    2.18 +			keepAliveCounter++;
    2.19 +			if (keepAliveCounter % (60 * 1000 / keepAliveInterval) == 0) logger->log(L::INFO, "Still sending periodic keep-alive messages (each " + std::to_string(keepAliveInterval) + " ms).");
    2.20  		}
    2.21  	}
    2.22  
    2.23 @@ -62,7 +66,7 @@
    2.24  	}
    2.25  
    2.26  	Bytes normalize(const Bytes& data) {
    2.27 -		if (data.size() % 2) throw std::invalid_argument("data before normalization must have even number of bytes");
    2.28 +		if (data.size() % 2) throw std::invalid_argument("Data before normalization must have even number of bytes.");
    2.29  		Bytes result;
    2.30  		result.reserve(data.size() / 2);
    2.31  		for (size_t i = 0; i < data.size() / 2; i++) result.push_back((data[i * 2] & 0x0F) << 4 | (data[i * 2 + 1] & 0x0F));
    2.32 @@ -111,7 +115,7 @@
    2.33  	}
    2.34  
    2.35  	template<typename T> std::vector<T> xOR(const std::vector<T>& a, const std::vector<T>& b) {
    2.36 -		if (a.size() != b.size()) throw std::invalid_argument("xor: both must be the same length");
    2.37 +		if (a.size() != b.size()) throw std::invalid_argument("Both must be the same length when doing XOR.");
    2.38  		std::vector<T> result;
    2.39  		result.reserve(a.size());
    2.40  		for (size_t i = 0; i < a.size(); i++) result.push_back(a[i] ^ b[i]);
    2.41 @@ -124,28 +128,30 @@
    2.42  	}
    2.43  
    2.44  	virtual ~DJMFixImpl() override {
    2.45 -		logger->log(L::FINE, "~DJMFixImpl()");
    2.46 +		logger->log(L::FINER, "~DJMFixImpl()");
    2.47  		if (running) stop();
    2.48  	}
    2.49  
    2.50  	void setMidiSender(MidiSender* midiSender) {
    2.51 -		logger->log(L::FINE, "DJMFixImpl::setMidiSender()");
    2.52 +		logger->log(L::FINER, "DJMFixImpl::setMidiSender()");
    2.53  		this->midiSender = midiSender;
    2.54  	}
    2.55  
    2.56  	virtual void receive(const MidiMessage& midiMessage) override {
    2.57 -		logger->log(L::INFO, "received message: size = " + std::to_string(midiMessage.size()) + " data = " + toString(midiMessage));
    2.58 +		logger->log(L::FINE, "Received a message: size = " + std::to_string(midiMessage.size()) + " data = " + toString(midiMessage));
    2.59  		std::lock_guard<std::recursive_mutex> lock(midiMutex);
    2.60  
    2.61  
    2.62  		if (midiMessage.size() == 12 && midiMessage[9] == 0x11) {
    2.63 +			logger->log(L::INFO, "Received greeting message.");
    2.64  			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});
    2.65 +			logger->log(L::INFO, "Sent message with seed1.");
    2.66  		} else if (midiMessage.size() == 54 && midiMessage[9] == 0x13 && midiMessage[33] == 0x04 && midiMessage[43] == 0x03) {
    2.67  			Bytes hash1(midiMessage.begin() + 35, midiMessage.begin() + 35 + 8);
    2.68  			seed2 = Bytes(midiMessage.begin() + 45, midiMessage.begin() + 45 + 8);
    2.69  			hash1 = normalize(hash1);
    2.70  			seed2 = normalize(seed2);
    2.71 -			logger->log(L::INFO, "got message with hash1 = " + toString(hash1) + " and seed2 = " + toString(seed2));
    2.72 +			logger->log(L::INFO, "Received message with hash1 = " + toString(hash1) + " and seed2 = " + toString(seed2));
    2.73  
    2.74  			Bytes seed0 = {0x68, 0x01, 0x31, 0xFB};
    2.75  			Bytes seed1 = {0x29, 0x00, 0x00, 0x00, 0x23, 0x48, 0x00, 0x00};
    2.76 @@ -153,13 +159,14 @@
    2.77  			Bytes hash1check = toBytes(fnv32hash(concat(seed1, xOR(seed0, seed2))));
    2.78  
    2.79  			if (equals(hash1, hash1check)) {
    2.80 -				logger->log(L::INFO, "hash1 verification: OK");
    2.81 +				logger->log(L::INFO, "Verification of hash1 was successful.");
    2.82  				Bytes hash2 = toBytes(fnv32hash(concat(seed2, xOR(seed0, seed2))));
    2.83  				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})));
    2.84 +				logger->log(L::INFO, "Sent message with hash2.");
    2.85  			} else {
    2.86  				std::stringstream logMessage;
    2.87  				logMessage
    2.88 -						<< "hash1 verification failed: "
    2.89 +						<< "Verification of hash1 failed: "
    2.90  						<< " midiMessage = " << toString(midiMessage)
    2.91  						<< " seed0 = " << toString(seed0)
    2.92  						<< " seed1 = " << toString(seed1)
    2.93 @@ -171,16 +178,18 @@
    2.94  			}
    2.95  		} else if (midiMessage.size() == 12 && midiMessage[9] == 0x15) {
    2.96  			sendKeepAlive = true;
    2.97 +			logger->log(L::INFO, "Received acknowledgment message. Started sending keep-alive messages. LINE/PHONO channels should work now.");
    2.98  		}
    2.99  
   2.100  	}
   2.101  
   2.102  	void start() override {
   2.103  		logger->log(L::FINE, "DJMFixImpl::start()");
   2.104 -		if (midiSender == nullptr) throw std::logic_error("need a midiSender when starting DJMFix");
   2.105 +		if (midiSender == nullptr) throw std::logic_error("Need a midiSender when starting DJMFix");
   2.106  
   2.107  		// TODO: methods for parsing and constructing messages from parts (TLV)
   2.108  		send({0xf0, 0x00, 0x40, 0x05, 0x00, 0x00, 0x00, 0x17, 0x00, 0x50, 0x01, 0xf7});
   2.109 +		logger->log(L::INFO, "Sent greeting message.");
   2.110  
   2.111  		keepAliveThread = std::thread(&DJMFixImpl::run, this);
   2.112  		running = true;
     3.1 --- a/djm-fix.cpp	Mon Jan 04 15:45:12 2021 +0100
     3.2 +++ b/djm-fix.cpp	Mon Jan 04 17:11:57 2021 +0100
     3.3 @@ -83,7 +83,7 @@
     3.4  	using L = djmfix::logging::Level;
     3.5  	std::unique_ptr<djmfix::logging::Logger> logger(djmfix::logging::create(std::cerr, L::INFO));
     3.6  	try {
     3.7 -		logger->log(L::INFO, "djm-fix started");
     3.8 +		logger->log(L::INFO, "DJM-Fix started.");
     3.9  		std::string cardNamePattern = argc == 2 ? argv[1] : "Pioneer DJ.*";
    3.10  
    3.11  		signal(SIGINT, interrupt);
    3.12 @@ -94,7 +94,7 @@
    3.13  		while (run) std::this_thread::sleep_for(std::chrono::milliseconds(100));
    3.14  		
    3.15  		std::cerr << std::endl;
    3.16 -		logger->log(L::INFO, "djm-fix stopping");
    3.17 +		logger->log(L::INFO, "DJM-Fix stopping.");
    3.18  		
    3.19  		alsaBridge->stop();
    3.20