Use logging framework for AudioPlayer

This commit is contained in:
ronaldheft
2022-09-06 21:32:32 -04:00
parent 639d641c07
commit 368f349c78
+31 -27
View File
@@ -19,6 +19,7 @@ enum PlayMethod:Int {
class AudioPlayer: NSObject { class AudioPlayer: NSObject {
internal let queue = DispatchQueue(label: "ABSAudioPlayerQueue") internal let queue = DispatchQueue(label: "ABSAudioPlayerQueue")
internal let logger = AppLogger(category: "AudioPlayer")
// enums and @objc are not compatible // enums and @objc are not compatible
@objc dynamic var status: Int @objc dynamic var status: Int
@@ -68,7 +69,7 @@ class AudioPlayer: NSObject {
let playbackSession = self.getPlaybackSession() let playbackSession = self.getPlaybackSession()
guard let playbackSession = playbackSession else { guard let playbackSession = playbackSession else {
NSLog("Failed to fetch playback session. Player will not initialize") logger.error("Failed to fetch playback session. Player will not initialize")
NotificationCenter.default.post(name: NSNotification.Name(PlayerEvents.failed.rawValue), object: nil) NotificationCenter.default.post(name: NSNotification.Name(PlayerEvents.failed.rawValue), object: nil)
return return
} }
@@ -86,10 +87,10 @@ class AudioPlayer: NSObject {
} }
self.currentTrackIndex = getItemIndexForTime(time: playbackSession.currentTime) self.currentTrackIndex = getItemIndexForTime(time: playbackSession.currentTime)
NSLog("Starting track index \(self.currentTrackIndex) for start time \(playbackSession.currentTime)") logger.debug("Starting track index \(self.currentTrackIndex) for start time \(playbackSession.currentTime)")
let playerItems = self.allPlayerItems[self.currentTrackIndex..<self.allPlayerItems.count] let playerItems = self.allPlayerItems[self.currentTrackIndex..<self.allPlayerItems.count]
NSLog("Setting player items \(playerItems.count)") logger.debug("Setting player items \(playerItems.count)")
for item in Array(playerItems) { for item in Array(playerItems) {
self.audioPlayer.insert(item, after:self.audioPlayer.items().last) self.audioPlayer.insert(item, after:self.audioPlayer.items().last)
@@ -99,7 +100,7 @@ class AudioPlayer: NSObject {
setupQueueObserver() setupQueueObserver()
setupQueueItemStatusObserver() setupQueueItemStatusObserver()
NSLog("Audioplayer ready") logger.debug("Audioplayer ready")
} }
deinit { deinit {
@@ -120,8 +121,8 @@ class AudioPlayer: NSObject {
do { do {
try AVAudioSession.sharedInstance().setActive(false) try AVAudioSession.sharedInstance().setActive(false)
} catch { } catch {
NSLog("Failed to set AVAudioSession inactive") logger.error("Failed to set AVAudioSession inactive")
print(error) logger.error(error)
} }
self.removeAudioSessionNotifications() self.removeAudioSessionNotifications()
@@ -214,14 +215,14 @@ class AudioPlayer: NSObject {
self.audioPlayer.currentItem.map { item in self.audioPlayer.currentItem.map { item in
self.currentTrackIndex = self.allPlayerItems.firstIndex(of:item) ?? 0 self.currentTrackIndex = self.allPlayerItems.firstIndex(of:item) ?? 0
if (self.currentTrackIndex != prevTrackIndex) { if (self.currentTrackIndex != prevTrackIndex) {
NSLog("New Current track index \(self.currentTrackIndex)") self.logger.debug("New Current track index \(self.currentTrackIndex)")
} }
} }
} }
} }
private func setupQueueItemStatusObserver() { private func setupQueueItemStatusObserver() {
NSLog("queueStatusObserver: Setting up") logger.debug("queueStatusObserver: Setting up")
// Listen for player item updates // Listen for player item updates
self.queueItemStatusObserver?.invalidate() self.queueItemStatusObserver?.invalidate()
@@ -236,13 +237,13 @@ class AudioPlayer: NSObject {
} }
private func handleQueueItemStatus(playerItem: AVPlayerItem) { private func handleQueueItemStatus(playerItem: AVPlayerItem) {
NSLog("queueStatusObserver: Current item status changed") logger.debug("queueStatusObserver: Current item status changed")
guard let playbackSession = self.getPlaybackSession() else { guard let playbackSession = self.getPlaybackSession() else {
NotificationCenter.default.post(name: NSNotification.Name(PlayerEvents.failed.rawValue), object: nil) NotificationCenter.default.post(name: NSNotification.Name(PlayerEvents.failed.rawValue), object: nil)
return return
} }
if (playerItem.status == .readyToPlay) { if (playerItem.status == .readyToPlay) {
NSLog("queueStatusObserver: Current Item Ready to play. PlayWhenReady: \(self.playWhenReady)") logger.debug("queueStatusObserver: Current Item Ready to play. PlayWhenReady: \(self.playWhenReady)")
// Seek the player before initializing, so a currentTime of 0 does not appear in MediaProgress / session // Seek the player before initializing, so a currentTime of 0 does not appear in MediaProgress / session
let firstReady = self.status < 0 let firstReady = self.status < 0
@@ -261,7 +262,7 @@ class AudioPlayer: NSObject {
self.play() self.play()
} }
} else if (playerItem.status == .failed) { } else if (playerItem.status == .failed) {
NSLog("queueStatusObserver: FAILED \(playerItem.error?.localizedDescription ?? "")") logger.error("queueStatusObserver: FAILED \(playerItem.error?.localizedDescription ?? "")")
NotificationCenter.default.post(name: NSNotification.Name(PlayerEvents.failed.rawValue), object: nil) NotificationCenter.default.post(name: NSNotification.Name(PlayerEvents.failed.rawValue), object: nil)
} }
} }
@@ -269,8 +270,8 @@ class AudioPlayer: NSObject {
private func startPausedTimer() { private func startPausedTimer() {
guard self.pausedTimer == nil else { return } guard self.pausedTimer == nil else { return }
self.queue.async { self.queue.async {
self.pausedTimer = Timer.scheduledTimer(withTimeInterval: 10, repeats: true) { timer in self.pausedTimer = Timer.scheduledTimer(withTimeInterval: 10, repeats: true) { [weak self] timer in
NSLog("PAUSE TIMER: Syncing from server") self?.logger.debug("PAUSE TIMER: Syncing from server")
Task { await PlayerProgress.shared.syncFromServer() } Task { await PlayerProgress.shared.syncFromServer() }
} }
} }
@@ -331,7 +332,7 @@ class AudioPlayer: NSObject {
} }
private func resumePlayback() { private func resumePlayback() {
NSLog("PLAY: Resuming playback") logger.debug("PLAY: Resuming playback")
// Stop the paused timer // Stop the paused timer
self.stopPausedTimer() self.stopPausedTimer()
@@ -348,7 +349,7 @@ class AudioPlayer: NSObject {
public func pause() { public func pause() {
guard self.isInitialized() else { return } guard self.isInitialized() else { return }
NSLog("PAUSE: Pausing playback") logger.debug("PAUSE: Pausing playback")
self.audioPlayer.pause() self.audioPlayer.pause()
self.markAudioSessionAs(active: false) self.markAudioSessionAs(active: false)
@@ -370,17 +371,17 @@ class AudioPlayer: NSObject {
self.pause() self.pause()
NSLog("SEEK: Seek to \(to) from \(from)") logger.debug("SEEK: Seek to \(to) from \(from)")
guard let playbackSession = self.getPlaybackSession() else { return } guard let playbackSession = self.getPlaybackSession() else { return }
let currentTrack = playbackSession.audioTracks[self.currentTrackIndex] let currentTrack = playbackSession.audioTracks[self.currentTrackIndex]
let ctso = currentTrack.startOffset ?? 0.0 let ctso = currentTrack.startOffset ?? 0.0
let trackEnd = ctso + currentTrack.duration let trackEnd = ctso + currentTrack.duration
NSLog("SEEK: Seek current track END = \(trackEnd)") logger.debug("SEEK: Seek current track END = \(trackEnd)")
let indexOfSeek = getItemIndexForTime(time: to) let indexOfSeek = getItemIndexForTime(time: to)
NSLog("SEEK: Seek to index \(indexOfSeek) | Current index \(self.currentTrackIndex)") logger.debug("SEEK: Seek to index \(indexOfSeek) | Current index \(self.currentTrackIndex)")
// Reconstruct queue if seeking to a different track // Reconstruct queue if seeking to a different track
if (self.currentTrackIndex != indexOfSeek) { if (self.currentTrackIndex != indexOfSeek) {
@@ -401,12 +402,15 @@ class AudioPlayer: NSObject {
setupQueueItemStatusObserver() setupQueueItemStatusObserver()
} else { } else {
NSLog("SEEK: Seeking in current item \(to)") logger.debug("SEEK: Seeking in current item \(to)")
let currentTrackStartOffset = playbackSession.audioTracks[self.currentTrackIndex].startOffset ?? 0.0 let currentTrackStartOffset = playbackSession.audioTracks[self.currentTrackIndex].startOffset ?? 0.0
let seekTime = to - currentTrackStartOffset let seekTime = to - currentTrackStartOffset
self.audioPlayer.seek(to: CMTime(seconds: seekTime, preferredTimescale: 1000)) { [weak self] completed in self.audioPlayer.seek(to: CMTime(seconds: seekTime, preferredTimescale: 1000)) { [weak self] completed in
guard completed else { return NSLog("SEEK: WARNING: seeking not completed (to \(seekTime)") } guard completed else {
self?.logger.debug("SEEK: WARNING: seeking not completed (to \(seekTime)")
return
}
guard let self = self else { return } guard let self = self else { return }
if continuePlaying { if continuePlaying {
@@ -422,7 +426,7 @@ class AudioPlayer: NSObject {
let playbackSpeedChanged = rate > 0.0 && rate != self.tmpRate && !(observed && rate == 1) let playbackSpeedChanged = rate > 0.0 && rate != self.tmpRate && !(observed && rate == 1)
if self.audioPlayer.rate != rate { if self.audioPlayer.rate != rate {
NSLog("setPlaybakRate rate changed from \(self.audioPlayer.rate) to \(rate)") logger.debug("setPlaybakRate rate changed from \(self.audioPlayer.rate) to \(rate)")
self.audioPlayer.rate = rate self.audioPlayer.rate = rate
} }
@@ -477,7 +481,7 @@ class AudioPlayer: NSObject {
} else if (playbackSession.playMethod == PlayMethod.local.rawValue) { } else if (playbackSession.playMethod == PlayMethod.local.rawValue) {
guard let localFile = track.getLocalFile() else { guard let localFile = track.getLocalFile() else {
// Worst case we can stream the file // Worst case we can stream the file
NSLog("Unable to play local file. Resulting to streaming \(track.localFileId ?? "Unknown")") logger.debug("Unable to play local file. Resulting to streaming \(track.localFileId ?? "Unknown")")
let filename = track.metadata?.filename ?? "" let filename = track.metadata?.filename ?? ""
let filenameEncoded = filename.addingPercentEncoding(withAllowedCharacters: NSCharacterSet.urlQueryAllowed) let filenameEncoded = filename.addingPercentEncoding(withAllowedCharacters: NSCharacterSet.urlQueryAllowed)
let urlstr = "\(Store.serverConfig!.address)/s/item/\(itemId)/\(filenameEncoded ?? "")?token=\(Store.serverConfig!.token)" let urlstr = "\(Store.serverConfig!.address)/s/item/\(itemId)/\(filenameEncoded ?? "")?token=\(Store.serverConfig!.token)"
@@ -497,8 +501,8 @@ class AudioPlayer: NSObject {
do { do {
try AVAudioSession.sharedInstance().setCategory(.playback, mode: .spokenAudio) try AVAudioSession.sharedInstance().setCategory(.playback, mode: .spokenAudio)
} catch { } catch {
NSLog("Failed to set AVAudioSession category") logger.error("Failed to set AVAudioSession category")
print(error) logger.error(error)
} }
} }
@@ -506,7 +510,7 @@ class AudioPlayer: NSObject {
do { do {
try AVAudioSession.sharedInstance().setActive(active) try AVAudioSession.sharedInstance().setActive(active)
} catch { } catch {
NSLog("Failed to set audio session as active=\(active)") logger.error("Failed to set audio session as active=\(active)")
} }
} }
@@ -637,11 +641,11 @@ class AudioPlayer: NSObject {
public override func observeValue(forKeyPath keyPath: String?, of object: Any?, change: [NSKeyValueChangeKey : Any]?, context: UnsafeMutableRawPointer?) { public override func observeValue(forKeyPath keyPath: String?, of object: Any?, change: [NSKeyValueChangeKey : Any]?, context: UnsafeMutableRawPointer?) {
if context == &playerContext { if context == &playerContext {
if keyPath == #keyPath(AVPlayer.rate) { if keyPath == #keyPath(AVPlayer.rate) {
NSLog("playerContext observer player rate") logger.debug("playerContext observer player rate")
self.setPlaybackRate(change?[.newKey] as? Float ?? 1.0, observed: true) self.setPlaybackRate(change?[.newKey] as? Float ?? 1.0, observed: true)
} else if keyPath == #keyPath(AVPlayer.currentItem) { } else if keyPath == #keyPath(AVPlayer.currentItem) {
NotificationCenter.default.post(name: NSNotification.Name(PlayerEvents.update.rawValue), object: nil) NotificationCenter.default.post(name: NSNotification.Name(PlayerEvents.update.rawValue), object: nil)
NSLog("WARNING: Item ended") logger.debug("WARNING: Item ended")
} }
} else { } else {
super.observeValue(forKeyPath: keyPath, of: object, change: change, context: context) super.observeValue(forKeyPath: keyPath, of: object, change: change, context: context)