Use the new async logging macros, fix various log messages

Author: padenot

Cargo.toml

@@ -11,7 +11,7 @@ crate-type = ["staticlib", "rlib"]
 atomic = "0.4"
 bitflags = "1.0"
 coreaudio-sys-utils = { path = "coreaudio-sys-utils" }
-cubeb-backend = "0.10"
+cubeb-backend = "0.10.1"
 float-cmp = "0.6"
 libc = "0.2"
 lazy_static = "1.2"

src/backend/buffer_manager.rs

@@ -208,7 +208,7 @@ impl BufferManager {
         };
         assert!(pushed <= to_push, "We don't support upmix");
         if pushed != to_push {
-            cubeb_log!(
+            cubeb_alog!(
                 "Input ringbuffer full, could only push {} instead of {}",
                 pushed,
                 to_push
@@ -222,6 +222,11 @@ impl BufferManager {
                     unsafe { slice::from_raw_parts_mut::<i16>(data as *mut i16, needed_samples) };
                 let read = p.pop_slice(input);
                 if read < needed_samples {
+                    cubeb_alog!(
+                        "Underrun during input data pull: (needed: {}, available: {})",
+                        needed_samples,
+                        read
+                    );
                     for i in 0..(needed_samples - read) {
                         input[read + i] = 0;
                     }
@@ -232,6 +237,11 @@ impl BufferManager {
                     unsafe { slice::from_raw_parts_mut::<f32>(data as *mut f32, needed_samples) };
                 let read = p.pop_slice(input);
                 if read < needed_samples {
+                    cubeb_alog!(
+                        "Underrun during input data pull: (needed: {}, available: {})",
+                        needed_samples,
+                        read
+                    );
                     for i in 0..(needed_samples - read) {
                         input[read + i] = 0.0;
                     }

src/backend/mixer.rs

@@ -180,7 +180,7 @@ impl Mixer {
         assert!(out_channel_count > 0);
 
         cubeb_log!(
-            "Create a mixer with input channel count: {}, input layout: {:?}, \
+            "Creating a mixer with input channel count: {}, input layout: {:?},\
              out channel count: {}, output channels: {:?}",
             in_channel_count,
             input_layout,
@@ -189,7 +189,9 @@ impl Mixer {
         );
 
         let input_channels = if in_channel_count as u32 != input_layout.bits().count_ones() {
-            cubeb_log!("Mismatch between input channels and layout. Apply default layout instead");
+            cubeb_log!(
+                "Mismatch between input channels and layout. Applying default layout instead"
+            );
             get_default_channel_order(in_channel_count)
         } else {
             get_channel_order(input_layout)

src/backend/mod.rs

@@ -199,7 +199,7 @@ fn create_device_info(devid: AudioDeviceID, devtype: DeviceType) -> Option<devic
     };
 
     if devid == kAudioObjectUnknown {
-        cubeb_log!("Use the system default device");
+        cubeb_log!("Using the system default device");
         flags |= device_flags::DEV_SELECTED_DEFAULT;
         get_default_device(devtype).map(|id| device_info { id, flags })
     } else {
@@ -390,7 +390,7 @@ extern "C" fn audiounit_input_callback(
             // output device is no longer valid and must be reset.
             // For now state that no error occurred and feed silence, stream will be
             // resumed once reinit has completed.
-            cubeb_logv!(
+            cubeb_alog!(
                 "({:p}) input: reinit pending, output will pull silence instead",
                 stm.core_stream_data.stm_ptr
             );
@@ -402,7 +402,7 @@ extern "C" fn audiounit_input_callback(
             ErrorHandle::Return(status)
         };
 
-        cubeb_logv!(
+        cubeb_alogv!(
             "({:p}) input: buffers {}, size {}, channels {}, rendered frames {}, total frames {}.",
             stm.core_stream_data.stm_ptr,
             input_buffer_list.mNumberBuffers,
@@ -530,7 +530,7 @@ extern "C" fn audiounit_output_callback(
     };
 
     if stm.stopped.load(Ordering::SeqCst) {
-        cubeb_log!("({:p}) output stopped.", stm as *const AudioUnitStream);
+        cubeb_alog!("({:p}) output stopped.", stm as *const AudioUnitStream);
         audiounit_make_silent(&mut buffers[0]);
         return NO_ERR;
     }
@@ -554,7 +554,7 @@ extern "C" fn audiounit_output_callback(
             .store(output_latency_frames, Ordering::SeqCst);
     }
 
-    cubeb_logv!(
+    cubeb_alogv!(
         "({:p}) output: buffers {}, size {}, channels {}, frames {}.",
         stm as *const AudioUnitStream,
         buffers.len(),
@@ -599,7 +599,7 @@ extern "C" fn audiounit_output_callback(
         if prev_frames_written == 0 && buffered_input_frames > input_frames_needed as usize {
             input_buffer_manager.trim(input_frames_needed);
             let popped_frames = buffered_input_frames - input_frames_needed as usize;
-            cubeb_log!("Dropping {} frames in input buffer.", popped_frames);
+            cubeb_alog!("Dropping {} frames in input buffer.", popped_frames);
         }
 
         let input_frames = if input_frames_needed > buffered_input_frames
@@ -609,7 +609,7 @@ extern "C" fn audiounit_output_callback(
         {
             // The silent frames will be inserted in `get_linear_data` below.
             let silent_frames_to_push = input_frames_needed - buffered_input_frames;
-            cubeb_log!(
+            cubeb_alog!(
                 "({:p}) Missing Frames: {} will append {} frames of input silence.",
                 stm.core_stream_data.stm_ptr,
                 if stm.frames_read.load(Ordering::SeqCst) == 0 {
@@ -716,7 +716,7 @@ extern "C" fn audiounit_property_listener_callback(
     let addrs = unsafe { slice::from_raw_parts(addresses, address_count as usize) };
     if stm.switching_device.load(Ordering::SeqCst) {
         cubeb_log!(
-            "Switching is already taking place. Skip Events for device {}",
+            "Switching is already taking place. Skipping event for device {}",
             id
         );
         return NO_ERR;
@@ -725,9 +725,8 @@ extern "C" fn audiounit_property_listener_callback(
 
     let mut input_device_dead = false;
 
-    // Log the events
     cubeb_log!(
-        "({:p}) Handle {} device changed events for device {}",
+        "({:p}) Handling {} device changed events for device {}",
         stm as *const AudioUnitStream,
         address_count,
         id
@@ -743,7 +742,7 @@ extern "C" fn audiounit_property_listener_callback(
 
     // Handle the events
     if input_device_dead {
-        cubeb_log!("The user-selected input device is dead, enter error state");
+        cubeb_log!("The user-selected input device is dead, entering error state");
         stm.stopped.store(true, Ordering::SeqCst);
         stm.core_stream_data.stop_audiounits();
         stm.close_on_error();
@@ -803,7 +802,7 @@ fn audiounit_convert_channel_layout(layout: &AudioChannelLayout) -> Vec<mixer::C
         // kAudioChannelLayoutTag_Mono
         // kAudioChannelLayoutTag_Stereo
         // ....
-        cubeb_log!("Only handle UseChannelDescriptions for now.\n");
+        cubeb_log!("Only handling UseChannelDescriptions for now.\n");
         return Vec::new();
     }
 
@@ -962,7 +961,7 @@ fn create_audiounit(device: &device_info) -> Result<AudioUnit> {
 
     set_device_to_audiounit(unit, device.id).map_err(|e| {
         cubeb_log!(
-            "Fail to set device {} to the created audiounit. Error: {}",
+            "Failed to set device {} to the created audiounit. Error: {}",
             device.id,
             e
         );
@@ -1158,7 +1157,7 @@ fn set_buffer_size_sync(unit: AudioUnit, devtype: DeviceType, frames: u32) -> Re
 
     set_buffer_size(unit, devtype, frames).map_err(|e| {
         cubeb_log!(
-            "Fail to set buffer size for AudioUnit {:?} for {:?}. Error: {}",
+            "Failed to set buffer size for AudioUnit {:?} for {:?}. Error: {}",
             unit,
             devtype,
             e
@@ -1172,7 +1171,7 @@ fn set_buffer_size_sync(unit: AudioUnit, devtype: DeviceType, frames: u32) -> Re
         let (chg, timeout_res) = cvar.wait_timeout(changed, waiting_time).unwrap();
         if timeout_res.timed_out() {
             cubeb_log!(
-                "Time out for waiting the buffer frame size setting of AudioUnit {:?} for {:?}",
+                "Timed out for waiting the buffer frame size setting of AudioUnit {:?} for {:?}",
                 unit,
                 devtype
             );
@@ -1303,7 +1302,7 @@ fn get_fixed_latency(devid: AudioObjectID, devtype: DeviceType) -> u32 {
     let stream_latency = get_device_streams(devid, devtype).and_then(|streams| {
         if streams.is_empty() {
             cubeb_log!(
-                "No any stream on device {} in {:?} scope!",
+                "No stream on device {} in {:?} scope!",
                 devid,
                 devtype
             );
@@ -1338,13 +1337,13 @@ fn get_device_group_id(
             match get_custom_group_id(id, devtype) {
                 Some(id) => return Ok(id),
                 None => {
-                    cubeb_log!("Get model uid instead.");
+                    cubeb_log!("Getting model UID instead.");
                 }
             };
         }
         Ok(trans_type) => {
             cubeb_log!(
-                "The transport type is {:?}. Get model uid instead.",
+                "The transport type is {:?}. Getting model UID instead.",
                 convert_uint32_into_string(trans_type)
             );
         }
@@ -1373,7 +1372,7 @@ fn get_custom_group_id(id: AudioDeviceID, devtype: DeviceType) -> Option<CString
         s @ Ok(IMIC) | s @ Ok(ISPK) => {
             const GROUP_ID: &str = "builtin-internal-mic|spk";
             cubeb_log!(
-                "Use hardcode group id: {} when source is: {:?}.",
+                "Using hardcode group id: {} when source is: {:?}.",
                 GROUP_ID,
                 convert_uint32_into_string(s.unwrap())
             );
@@ -1382,7 +1381,7 @@ fn get_custom_group_id(id: AudioDeviceID, devtype: DeviceType) -> Option<CString
         s @ Ok(EMIC) | s @ Ok(HDPN) => {
             const GROUP_ID: &str = "builtin-external-mic|hdpn";
             cubeb_log!(
-                "Use hardcode group id: {} when source is: {:?}.",
+                "Using hardcode group id: {} when source is: {:?}.",
                 GROUP_ID,
                 convert_uint32_into_string(s.unwrap())
             );
@@ -1444,7 +1443,7 @@ fn create_cubeb_device_info(
         }
         Err(e) => {
             cubeb_log!(
-                "Cannot get the uid for device {} in {:?} scope. Error: {}",
+                "Cannot get the UID for device {} in {:?} scope. Error: {}",
                 devid,
                 devtype,
                 e
@@ -1458,7 +1457,7 @@ fn create_cubeb_device_info(
         }
         Err(e) => {
             cubeb_log!(
-                "Cannot get the model uid for device {} in {:?} scope. Error: {}",
+                "Cannot get the model UID for device {} in {:?} scope. Error: {}",
                 devid,
                 devtype,
                 e
@@ -1547,7 +1546,7 @@ fn create_cubeb_device_info(
             latency + range.mMaximum as u32,
         ),
         Err(e) => {
-            cubeb_log!("Cannot get the buffer frame size for device {} in {:?} scope. Use default value instead. Error: {}", devid, devtype, e);
+            cubeb_log!("Cannot get the buffer frame size for device {} in {:?} scope. Using default value instead. Error: {}", devid, devtype, e);
             (
                 10 * dev_info.default_rate / 1000,
                 100 * dev_info.default_rate / 1000,
@@ -1659,7 +1658,7 @@ fn audiounit_get_devices_of_type(devtype: DeviceType) -> Vec<AudioObjectID> {
         let info = format!("{} ({})", device, label);
 
         if let Ok(channels) = get_channel_count(device, devtype) {
-            cubeb_log!("device {} has {} {:?}-channels", info, channels, devtype);
+            cubeb_log!("Device {} has {} {:?}-channels", info, channels, devtype);
             if channels > 0 {
                 devices_in_scope.push(device);
             }
@@ -1755,7 +1754,7 @@ impl DevicesData {
     }
 
     fn is_empty(&self) -> bool {
-        self.changed_callback == None && self.callback_user_ptr.is_null() && self.devices.is_empty()
+        self.changed_callback.is_none()  && self.callback_user_ptr.is_null() && self.devices.is_empty()
     }
 }
 
@@ -2350,17 +2349,32 @@ impl<'ctx> CoreStreamData<'ctx> {
         // It's impossible to create an aggregate device from an aggregate device, and it's
         // unnecessary to create an aggregate device when opening the same device input/output. In
         // all other cases, use an aggregate device.
-
         let mut either_already_aggregate = false;
         if self.has_input() {
-            either_already_aggregate |=
+            let input_is_aggregate =
                 get_device_transport_type(self.input_device.id, DeviceType::INPUT).unwrap_or(0)
                     == kAudioDeviceTransportTypeAggregate;
+            if input_is_aggregate {
+                either_already_aggregate = true;
+            }
+            cubeb_log!(
+                "Input device ID: {} (aggregate: {:?})",
+                self.input_device.id,
+                input_is_aggregate
+            );
         }
         if self.has_output() {
-            either_already_aggregate |=
+            let output_is_aggregate =
                 get_device_transport_type(self.output_device.id, DeviceType::OUTPUT).unwrap_or(0)
                     == kAudioDeviceTransportTypeAggregate;
+            if output_is_aggregate {
+                either_already_aggregate = true;
+            }
+            cubeb_log!(
+                "Output device ID: {} (aggregate: {:?})",
+                self.input_device.id,
+                output_is_aggregate
+            );
         }
         // Only use an aggregate device when the device are different.
         self.has_input()
@@ -2437,15 +2451,15 @@ impl<'ctx> CoreStreamData<'ctx> {
                     out_dev_info.flags = device_flags::DEV_OUTPUT;
                     self.aggregate_device = Some(device);
                     cubeb_log!(
-                        "({:p}) Use aggregate device {} for input and output.",
+                        "({:p}) Using an aggregate device {} for input and output.",
                         self.stm_ptr,
                         self.aggregate_device.as_ref().unwrap().get_device_id()
                     );
                 }
                 Err(e) => {
                     cubeb_log!(
-                        "({:p}) Create aggregate devices failed. Error: {}.\
-                         Use assigned devices directly instead.",
+                        "({:p}) Creation of aggregate devices failed. Error: {}.\
+                         Using assigned devices directly instead.",
                         self.stm_ptr,
                         e
                     );
@@ -2461,7 +2475,7 @@ impl<'ctx> CoreStreamData<'ctx> {
         // Configure I/O stream
         if self.has_input() {
             cubeb_log!(
-                "({:p}) Initialize input by device info: {:?}",
+                "({:p}) Initializing input by device info: {:?}",
                 self.stm_ptr,
                 in_dev_info
             );