cleanup log messages

5 files changed, 70 insertions, 39 deletions

diff --git a/Adlib.cpp b/Adlib.cpp
index 3033c4e..efd93c0 100644
--- a/Adlib.cpp
+++ b/Adlib.cpp
@@ -50,6 +50,9 @@
 #define LOG_ENABLED 1
 #define LOG_ENABLE_FLOW 1
 #define LOG_GROUP LOG_GROUP_DEV_SB16
+    // Log level 3 is used for register reads/writes
+    // Log level 7 is used for all port in/out
+    // Log level 9 is used for PCM rendering
 #include <VBox/vmm/pdmdev.h>
 #include <VBox/AssertGuest.h>
 #include <VBox/version.h>
@@ -178,7 +181,6 @@ static uint64_t adlibCalculateTimerExpire(PPDMDEVINS pDevIns, uint8_t value, uin
     uint64_t freq = PDMDevHlpTMTimeVirtGetFreq(pDevIns);
     uint64_t delay_ticks = (delay_usec * freq) / 1000000UL /*1usec in hz*/;
     uint64_t now_ticks = PDMDevHlpTMTimeVirtGet(pDevIns);
-    Log3Func(("value=%02x delay_usec=%llu virtfreq=%llu now_ticks=%llu delay_ticks=%llu\n", value, delay_usec, freq, now_ticks, delay_ticks));
     return now_ticks + delay_ticks;
 }
 
@@ -208,13 +210,13 @@ static DECLCALLBACK(int) adlibRenderThread(RTTHREAD ThreadSelf, void *pvUser)
 
     while (!ASMAtomicReadBool(&pThis->fShutdown)
            && ASMAtomicReadU64(&pThis->tmLastWrite) + ADLIB_RENDER_SUSPEND_TIMEOUT >= RTTimeSystemMilliTS()) {
-        Log3(("rendering %lld frames\n", buf_frames));
+        Log9(("rendering %lld frames\n", buf_frames));
 
         RTCritSectEnter(&pThis->critSect);
         OPL3_GenerateStream(&pThis->opl, buf, buf_frames);
         RTCritSectLeave(&pThis->critSect);
 
-        Log3(("writing %lld frames\n", buf_frames));
+        Log9(("writing %lld frames\n", buf_frames));
 
         ssize_t written_frames = pPcmOut->write(buf, buf_frames);
         if (written_frames < 0) {
@@ -295,7 +297,7 @@ static void adlibWakeRenderThread(PPDMDEVINS pDevIns)
         pThis->fShutdown = false;
         pThis->fStopped = false;
 
-        Log2(("Creating render thread\n"));
+        Log3(("Creating render thread\n"));
 
         int rc = RTThreadCreateF(&pThis->hRenderThread, adlibRenderThread, pThis, 0,
                                  RTTHREADTYPE_IO, RTTHREADFLAGS_WAITABLE,
@@ -316,7 +318,7 @@ static uint8_t adlibReadStatus(PPDMDEVINS pDevIns)
 
     uint64_t tmNow = PDMDevHlpTMTimeVirtGet(pDevIns);
 
-    Log3Func(("tmNow=%llu timer1=%llu timer2=%llu\n", tmNow,
+    Log5Func(("tmNow=%llu timer1=%llu timer2=%llu\n", tmNow,
               pThis->timer1Enable ? pThis->timer1Expire : 0,
               pThis->timer2Enable ? pThis->timer2Expire : 0));
 
@@ -331,7 +333,7 @@ static uint8_t adlibReadStatus(PPDMDEVINS pDevIns)
         status |= 0x6;
     }
 
-    Log2Func(("status=0x%x\n", status));
+    Log3Func(("status=0x%x\n", status));
 
     return status;
 }
@@ -343,7 +345,7 @@ static void adlibWriteRegister(PPDMDEVINS pDevIns, uint16_t reg, uint8_t value)
     // Any write to a register causes the render thread to be waken up
     adlibWakeRenderThread(pDevIns);
 
-    Log2Func(("0x%x = 0x%x\n", reg, value));
+    Log3Func(("0x%x = 0x%x\n", reg, value));
 
     switch (reg)
     {
@@ -433,7 +435,7 @@ static DECLCALLBACK(VBOXSTRICTRC) adlibIoPortRead(PPDMDEVINS pDevIns, void *pvUs
                 break;
         }
 
-        Log3Func(("read port %u: %#04x\n", offPort, uValue));
+        Log7Func(("read port %u: %#04x\n", offPort, uValue));
 
         *pu32 = uValue;
         return VINF_SUCCESS;
@@ -451,7 +453,7 @@ static DECLCALLBACK(VBOXSTRICTRC) adlibIoPortWrite(PPDMDEVINS pDevIns, void *pvU
     if (cb == 1)
     {
         PADLIBSTATE pThis = PDMDEVINS_2_DATA(pDevIns, PADLIBSTATE);
-        Log3Func(("write port %u: %#04x\n", offPort, u32));
+        Log7Func(("write port %u: %#04x\n", offPort, u32));
 
         uint8_t val = u32;
 
diff --git a/Mpu401.cpp b/Mpu401.cpp
index a84493e..cb7606b 100644
--- a/Mpu401.cpp
+++ b/Mpu401.cpp
@@ -50,6 +50,9 @@
 #define LOG_ENABLED 1
 #define LOG_ENABLE_FLOW 1
 #define LOG_GROUP LOG_GROUP_DEV_SB16
+    // Log level 3 is used for commands, responses, etc.
+    // Log level 5 is used for MIDI data in/out
+    // Log level 7 is used for all port in/out
 #include <VBox/vmm/pdmdev.h>
 #include <VBox/AssertGuest.h>
 #include <VBox/version.h>
@@ -120,6 +123,12 @@ static void mpuReset(PPDMDEVINS pDevIns)
 {
     PMPUSTATE pThis = PDMDEVINS_2_DATA(pDevIns, PMPUSTATE);
 
+    pThis->midi.reset();
+
+    if (pThis->fModeUart) {
+        Log(("Leaving UART mode"));
+    }
+
     pThis->fModeUart = false;
     pThis->fHaveInput = false;
     pThis->uInput = 0;
@@ -129,6 +138,8 @@ static void mpuRespondData(PPDMDEVINS pDevIns, uint8_t data)
 {
     PMPUSTATE pThis = PDMDEVINS_2_DATA(pDevIns, PMPUSTATE);
 
+    Log3Func(("enqueing response=0x%x\n", data));
+
     pThis->fHaveInput = true;
     pThis->uInput = data;
 }
@@ -145,8 +156,8 @@ static uint8_t mpuReadData(PPDMDEVINS pDevIns)
     if (pThis->fModeUart) {
         uint8_t data;
         ssize_t read = pThis->midi.read(&data, 1);
-        Log3Func(("read = %lld\n", read));
         if (read == 1) {
+            Log5Func(("midi_in data=0x%x\n", data));
             return data;
         }
     }
@@ -162,7 +173,9 @@ static void mpuWriteData(PPDMDEVINS pDevIns, uint8_t data)
 
     if (pThis->fModeUart) {
         ssize_t written = pThis->midi.write(&data, 1);
-        Log3Func(("written = %lld\n", written));
+        if (written == 1) {
+            Log5Func(("midi_out data=0x%x\n", data));
+        }
     } else {
         LogWarnFunc(("Ignoring data, not in UART mode\n"));
     }
@@ -197,7 +210,7 @@ static uint8_t mpuReadStatus(PPDMDEVINS pDevIns)
         status |= RT_BIT(7);
     }
 
-    LogFlow(("mpu status: outputReady=%RTbool inputReady=%RTbool\n", outputReady, inputReady));
+    Log5(("mpu status: outputReady=%RTbool inputReady=%RTbool\n", outputReady, inputReady));
 
     return status;
 }
@@ -206,6 +219,8 @@ static void mpuDoCommand(PPDMDEVINS pDevIns, uint8_t cmd)
 {
     PMPUSTATE pThis = PDMDEVINS_2_DATA(pDevIns, PMPUSTATE);
 
+    Log3Func(("cmd = 0x%x\n", cmd));
+
     if (pThis->fModeUart) {
         switch (cmd) {
             case MPU_COMMAND_RESET:
@@ -213,7 +228,7 @@ static void mpuDoCommand(PPDMDEVINS pDevIns, uint8_t cmd)
                 mpuRespondData(pDevIns, MPU_RESPONSE_ACK);
                 break;
             default:
-                LogWarnFunc(("Unknown command in UART mode: 0x%hx", cmd));
+                LogWarnFunc(("Unknown command in UART mode: 0x%hx\n", cmd));
                 break;
         }
     } else {
@@ -224,12 +239,13 @@ static void mpuDoCommand(PPDMDEVINS pDevIns, uint8_t cmd)
                 mpuRespondData(pDevIns, MPU_RESPONSE_ACK);
                 break;
             case MPU_COMMAND_ENTER_UART:
-                Log(("Entering UART mode"));
+                Log(("Entering UART mode\n"));
                 pThis->fModeUart = true;
                 mpuRespondData(pDevIns, MPU_RESPONSE_ACK);
                 break;
             default:
-                LogWarnFunc(("Unknown command in normal mode: 0x%hx", cmd));
+                LogWarnFunc(("Unknown command in normal mode: 0x%hx\n", cmd));
+                mpuRespondData(pDevIns, MPU_RESPONSE_ACK);
                 break;
         }
     }
@@ -261,7 +277,7 @@ static DECLCALLBACK(VBOXSTRICTRC) mpuIoPortRead(PPDMDEVINS pDevIns, void *pvUser
                 break;
         }
 
-        LogFunc(("read port %u: %#04x\n", offPort, uValue));
+        Log7Func(("read port %u: %#04x\n", offPort, uValue));
 
         *pu32 = uValue;
         return VINF_SUCCESS;
@@ -278,7 +294,7 @@ static DECLCALLBACK(VBOXSTRICTRC) mpuIoPortWrite(PPDMDEVINS pDevIns, void *pvUse
     RT_NOREF(pvUser);
     if (cb == 1)
     {
-        LogFunc(("write port %u: %#04x\n", offPort, u32));
+        Log7Func(("write port %u: %#04x\n", offPort, u32));
 
         switch (offPort)
         {
@@ -361,7 +377,7 @@ static DECLCALLBACK(int) mpuR3Construct(PPDMDEVINS pDevIns, int iInstance, PCFGM
     if (RT_FAILURE(rc))
         return PDMDEV_SET_ERROR(pDevIns, rc, N_("Failed to query \"Port\" from the config"));
 
-    Log(("mpu401#%i: Configuring on port 0x%x\n", iInstance, pThis->uPort));
+    LogFlowFunc(("mpu401#%i: port 0x%x\n", iInstance, pThis->uPort));
 
     /*
      * Initialize the device state.
diff --git a/midialsa.cpp b/midialsa.cpp
index 03d5699..d9c36ed 100644
--- a/midialsa.cpp
+++ b/midialsa.cpp
@@ -33,14 +33,14 @@ static ssize_t rawmidi_avail(snd_rawmidi_t *rmidi)
 
     int nfds = snd_rawmidi_poll_descriptors(rmidi, pfds, MAX_POLL_FDS);
     if (nfds <= 0) {
-        LogWarn(("ALSA rawmidi avail: no descriptors to poll!"));
+        LogWarn(("ALSA rawmidi avail: no descriptors to poll!\n"));
         return VERR_AUDIO_ENUMERATION_FAILED;
     }
 
     int ready = poll(pfds, nfds, 0);
     if (ready < 0) {
         if (errno != EAGAIN && errno != EINTR) {
-            LogWarnFunc(("Cannot poll, errno=%d", errno));
+            LogWarnFunc(("Cannot poll, errno=%d\n", errno));
             return VERR_AUDIO_STREAM_NOT_READY;
         }
         return 0;
@@ -50,15 +50,15 @@ static ssize_t rawmidi_avail(snd_rawmidi_t *rmidi)
         unsigned short revents;
         int err = snd_rawmidi_poll_descriptors_revents(rmidi, pfds, nfds, &revents);
         if (err != 0) {
-            LogWarnFunc(("Cannot call revents, err=%d", err));
+            LogWarnFunc(("Cannot call revents, err=%d\n", err));
             return VERR_AUDIO_STREAM_NOT_READY;
         }
 
         if (revents & POLLNVAL) {
-            LogWarnFunc(("POLLNVAL"));
+            LogWarnFunc(("POLLNVAL\n"));
         }
         if (revents & POLLERR) {
-            LogWarnFunc(("POLLERR"));
+            LogWarnFunc(("POLLERR\n"));
         }
 
         return revents & (POLLIN | POLLOUT);
@@ -112,7 +112,7 @@ ssize_t MIDIAlsa::write(uint8_t *data, size_t len)
 {
     ssize_t result = snd_rawmidi_write(_out, data, len);
     if (result < 0) {
-        LogWarn(("ALSA midi write error: %s", snd_strerror(result)));
+        LogWarn(("ALSA midi write error: %s\n", snd_strerror(result)));
         return VERR_AUDIO_STREAM_NOT_READY;
     }
     return result;
@@ -125,10 +125,21 @@ ssize_t MIDIAlsa::readAvail()
 
 ssize_t MIDIAlsa::read(uint8_t *buf, size_t len)
 {
-    ssize_t result = snd_rawmidi_read(_out, buf, len);
+    ssize_t result = snd_rawmidi_read(_in, buf, len);
     if (result < 0) {
-        LogWarn(("ALSA midi read error: %s", snd_strerror(result)));
+        LogWarn(("ALSA midi read error: %s\n", snd_strerror(result)));
         return VERR_AUDIO_STREAM_NOT_READY;
     }
     return result;
 }
+
+int MIDIAlsa::reset()
+{
+    if (_in) {
+        snd_rawmidi_drop(_in);
+    }
+    if (_out) {
+        snd_rawmidi_drop(_out);
+    }
+    return VINF_SUCCESS;
+}
diff --git a/midialsa.h b/midialsa.h
index e10c5f2..f41200b 100644
--- a/midialsa.h
+++ b/midialsa.h
@@ -39,6 +39,8 @@ public:
     ssize_t readAvail();
     ssize_t read(uint8_t *buf, size_t len);
 
+    int reset();
+
 private:
     snd_rawmidi_t *_in;
     snd_rawmidi_t *_out;
diff --git a/pcmalsa.cpp b/pcmalsa.cpp
index 5708509..a80befd 100644
--- a/pcmalsa.cpp
+++ b/pcmalsa.cpp
@@ -128,42 +128,42 @@ int PCMOutAlsa::setParams(unsigned int sampleRate, unsigned int channels, unsign
     /* choose all parameters */
     err = snd_pcm_hw_params_any(_pcm, hwparams);
     if (err < 0) {
-        LogWarnFunc(("Broken PCM configuration: no configurations available: %s", snd_strerror(err)));
+        LogWarnFunc(("Broken PCM configuration: no configurations available: %s\n", snd_strerror(err)));
         return err;
     }
     /* set software resampling */
     err = snd_pcm_hw_params_set_rate_resample(_pcm, hwparams, 1);
     if (err < 0) {
-        LogWarnFunc(("Resampling setup failed: %s", snd_strerror(err)));
+        LogWarnFunc(("Resampling setup failed: %s\n", snd_strerror(err)));
         return err;
     }
     /* set the selected read/write format */
     err = snd_pcm_hw_params_set_access(_pcm, hwparams, SND_PCM_ACCESS_RW_INTERLEAVED);
     if (err < 0) {
-        LogWarnFunc(("Access type not available: %s", snd_strerror(err)));
+        LogWarnFunc(("Access type not available: %s\n", snd_strerror(err)));
         return err;
     }
     /* set the sample format */
     err = snd_pcm_hw_params_set_format(_pcm, hwparams, SND_PCM_FORMAT_S16);
     if (err < 0) {
-        LogWarnFunc(("Sample format not available: %s", snd_strerror(err)));
+        LogWarnFunc(("Sample format not available: %s\n", snd_strerror(err)));
         return err;
     }
     /* set the count of channels */
     err = snd_pcm_hw_params_set_channels(_pcm, hwparams, channels);
     if (err < 0) {
-        LogWarnFunc(("Channels count (%i) not available: %s", channels, snd_strerror(err)));
+        LogWarnFunc(("Channels count (%i) not available: %s\n", channels, snd_strerror(err)));
         return err;
     }
     /* set the stream rate */
     unsigned int rrate = sampleRate;
     err = snd_pcm_hw_params_set_rate_near(_pcm, hwparams, &rrate, 0);
     if (err < 0) {
-        LogWarnFunc(("Rate %iHz not available for playback: %s", sampleRate, snd_strerror(err)));
+        LogWarnFunc(("Rate %iHz not available for playback: %s\n", sampleRate, snd_strerror(err)));
         return err;
     }
     if (rrate != sampleRate) {
-        LogWarnFunc(("Rate doesn't match (requested %iHz, get %iHz)", sampleRate, rrate));
+        LogWarnFunc(("Rate doesn't match (requested %iHz, get %iHz)\n", sampleRate, rrate));
         return -EINVAL;
     }
 
@@ -194,35 +194,35 @@ int PCMOutAlsa::setParams(unsigned int sampleRate, unsigned int channels, unsign
     /* write the parameters to device */
     err = snd_pcm_hw_params(_pcm, hwparams);
     if (err < 0) {
-        LogWarnFunc(("Unable to set hw params: %s", snd_strerror(err)));
+        LogWarnFunc(("Unable to set hw params: %s\n", snd_strerror(err)));
         return err;
     }
 
-    LogFunc(("Using bufferSize=%lu periodSize=%lu\n", _bufferSize, _periodSize));
+    Log2Func(("using bufferSize=%lu periodSize=%lu\n", _bufferSize, _periodSize));
 
     /* get the current swparams */
     err = snd_pcm_sw_params_current(_pcm, swparams);
     if (err < 0) {
-        LogWarnFunc(("Unable to determine current swparams: %s", snd_strerror(err)));
+        LogWarnFunc(("Unable to determine current swparams: %s\n", snd_strerror(err)));
         return err;
     }
     /* start the transfer when the buffer is almost full: */
     /* (buffer_size / avail_min) * avail_min */
     err = snd_pcm_sw_params_set_start_threshold(_pcm, swparams, (_bufferSize / _periodSize) * _periodSize);
     if (err < 0) {
-        LogWarnFunc(("Unable to set start threshold mode: %s", snd_strerror(err)));
+        LogWarnFunc(("Unable to set start threshold mode: %s\n", snd_strerror(err)));
         return err;
     }
     /* allow the transfer when at least period_size samples can be processed */
     err = snd_pcm_sw_params_set_avail_min(_pcm, swparams, _periodSize);
     if (err < 0) {
-        LogWarnFunc(("Unable to set avail min: %s", snd_strerror(err)));
+        LogWarnFunc(("Unable to set avail min: %s\n", snd_strerror(err)));
         return err;
     }
     /* write the parameters to the playback device */
     err = snd_pcm_sw_params(_pcm, swparams);
     if (err < 0) {
-        LogWarnFunc(("Unable to set sw params: %s", snd_strerror(err)));
+        LogWarnFunc(("Unable to set sw params: %s\n", snd_strerror(err)));
         return err;
     }