View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0012035 | MMA | General | public | 2014-04-30 11:13 | 2014-09-28 01:30 |
| Reporter | marek | Assigned To | |||
| Priority | immediate | Severity | major | Reproducibility | random |
| Status | closed | Resolution | fixed | ||
| Product Version | 1.0.5 | ||||
| Target Version | 1.0.5 | Fixed in Version | 1.0.6 | ||
| Summary | 0012035: Database becomes corrupted in some cases | ||||
| Description | We are observing some DB issues that are observed on some devices. It is mostly caused by playlist._data column that uses UNIQUE constraint. It's index becomes sometimes corrupted and it leads to duplicates in unique column. Possible causes: A. There are some useful tips how to avoid corruption of DB: http://sqlite.org/howtocorrupt.html . Paragraph 3.1 is probably most interesting for us. We are using WAL with checkpoints. These checkpoints are used quite often before DB is copied to external storage. I have added some logs to be able to see whether corruption can occur during copying. B. Maybe it is somehow related to locking issue. Sometimes the DB is locked. | ||||
| Steps To Reproduce | I have put integrity check to MediaStore sync (at the beginning and at the end) 1. Clean all (uninstall and delete MediaMonkey dir) 2. Start MMA 3. MediaStore sync starts - integrity is ok 4. Play something 5. Start manually mediastore from options - if integrity is OK - repeat 4, 5 | ||||
| Tags | No tags attached. | ||||
| Attached Files | log01-no publish.txt (22,774 bytes)
04-30 20:41:17.528: D/MediaMonkeyStoreProvider 1(13465): Query: /slavereadonly/audio/media/15;Projection:[_id, title, _data, album, album_id, artists, track, year, _ms_id, duration, bookmark, playcount, skipcount, type, volume_leveling, album_art, rating, lyrics, mime_type, guid, idfolder];Selection:null;Args:null
04-30 20:41:17.538: D/Provider(13465): Integrity check OK
04-30 20:41:17.558: D/Provider(13465): Integrity check OK
04-30 20:41:17.578: D/TrackFactory(13465): Get track instance for type: 0
04-30 20:41:17.578: D/AudioTrack(13465): PATH:/storage/emulated/0/Music/aaa BigFast/04 [Untitled].mp3
04-30 20:41:17.578: D/MediaAddable(13465): Set current track immediatelly
04-30 20:41:17.608: D/dalvikvm(13465): GC_FOR_ALLOC freed 1118K, 10% free 11399K/12580K, paused 25ms, total 25ms
04-30 20:41:17.608: D/TrackList 1(13465): addAsCurrentTrack t!=null?true
04-30 20:41:17.618: I/TrackList(13465): setCurrentTrack: AudioTrack storeToPreferences:false
04-30 20:41:17.618: D/TrackList(13465): clearTrackIndexes
04-30 20:41:17.618: D/TrackListModel(13465): SaveCurrentTrackInfo only
04-30 20:41:17.618: D/TrackListModel(13465): storeCurrentTrackInfo: InfoTrack: [Untitled]-Lamb (Fear of Fours)
04-30 20:41:17.618: I/TrackListModel(13465): getCurrentTrackInfo
04-30 20:41:17.618: W/PlayerStateInformator(13465): No track si set as current!
04-30 20:41:17.628: D/PlaybackService(13465): onCurrentTrackChange
04-30 20:41:17.628: D/PlaybackService(13465): onCurrentTrackChange AudioTrack
04-30 20:41:17.628: D/PlaybackService(13465): play
04-30 20:41:17.628: W/PlaybackService(13465): gainAudioFocus()
04-30 20:41:17.628: W/PlaybackService(13465): registerMediaButtonEventReceiver on checkRemoteControlClientCompact
04-30 20:41:17.628: I/PlaybackService(13465): registerMediaButtonEventReceiver
04-30 20:41:17.638: D/PlaybackService(13465): mPlayer.setNormalVolume
04-30 20:41:17.638: D/PlaybackService(13465): Track can be played AudioTrack
04-30 20:41:17.638: D/TrackList(13465): playCurrentTrack
04-30 20:41:17.648: D/AudioPlayer(13465): setPlayerState to: PLAYING
04-30 20:41:17.658: D/AudioPlayer(13465): initTimePlayedInSession
04-30 20:41:17.658: D/PlaybackService(13465): enableEqualizerIfNeeded
04-30 20:41:17.658: D/EqualizerModel(13465): isEnabledEqualizer:false
04-30 20:41:17.658: D/PlaybackService(13465): updateRemoteMetadata(supported:true) - TrackInfo:[Untitled]
04-30 20:41:17.658: W/PlaybackService(13465): updating RemoteControl state!
04-30 20:41:17.668: D/PlaybackService(13465): updateRemotePlaybackPosition
04-30 20:41:17.668: V/PlaybackService(13465): updateRemoteMetadata: [Untitled]
04-30 20:41:17.668: D/PlaybackService 3(13465): currentTrack.getAlbumArt: file:///storage/emulated/0/Android/data/com.android.providers.media/albumthumbs/1381928440528
04-30 20:41:17.698: D/dalvikvm(13465): GC_FOR_ALLOC freed 593K, 10% free 11381K/12580K, paused 27ms, total 27ms
04-30 20:41:17.698: I/dalvikvm-heap(13465): Grow heap (frag case) to 11.538MB for 409616-byte allocation
04-30 20:41:17.728: D/dalvikvm(13465): GC_FOR_ALLOC freed <1K, 10% free 11781K/12984K, paused 26ms, total 26ms
04-30 20:41:17.728: D/PlaybackService(13465): RemoteControlClientCompat available: true
04-30 20:41:17.728: D/PlaybackService(13465): albumArt width:320 height:320
04-30 20:41:17.738: D/PlaybackService 3(13465): currentTrack.getAlbumArt is not null true
04-30 20:41:17.738: I/PlaybackService(13465): refreshSuppressNotificationSounds
04-30 20:41:17.738: D/GlobalPreferences(13465): isSuppressNotificationSounds: false
04-30 20:41:17.738: D/UIUtils(13465): isAppVisible: true
04-30 20:41:17.738: D/PlaybackService(13465): updateNotification app is : in foreground isInKeyguardRestrictedInputMode: false
04-30 20:41:17.738: D/UIUtils(13465): isAppVisible: true
04-30 20:41:17.748: D/PlaybackService(13465): T2 show notification when player is playing
04-30 20:41:17.748: D/PlaybackService(13465): showNotification is Playing: true playerState: PLAYING
04-30 20:41:17.748: D/PlaybackService(13465): mUseLockScreenPlayer false
04-30 20:41:17.748: D/PlaybackService(13465): receiverRegistered false
04-30 20:41:17.748: D/PlaybackService(13465): updateWidgets tracklist is loaded
04-30 20:41:17.748: I/TrackList(13465): hasNextTrack
04-30 20:41:17.748: I/BitmapUtils(13465): albumArt:file:///storage/emulated/0/Android/data/com.android.providers.media/albumthumbs/1381928440528
04-30 20:41:17.778: D/dalvikvm(13465): GC_FOR_ALLOC freed 369K, 10% free 11903K/13112K, paused 24ms, total 25ms
04-30 20:41:17.788: D/PlaybackNotification(13465): prepareStopButton
04-30 20:41:17.788: I/BitmapUtils(13465): albumArt:file:///storage/emulated/0/Android/data/com.android.providers.media/albumthumbs/1381928440528
04-30 20:41:17.818: D/dalvikvm(13465): GC_FOR_ALLOC freed 234K, 10% free 12006K/13292K, paused 25ms, total 25ms
04-30 20:41:17.818: I/dalvikvm-heap(13465): Grow heap (frag case) to 12.147MB for 409616-byte allocation
04-30 20:41:17.848: D/dalvikvm(13465): GC_FOR_ALLOC freed <1K, 10% free 12406K/13696K, paused 28ms, total 28ms
04-30 20:41:17.848: D/PlaybackNotification(13465): prepareStopButton
04-30 20:41:17.888: D/BroadcastSender 1(13465): SEND STATE_CHANGE_ACTION
04-30 20:41:17.928: D/TrackList(13465): Notify changes 1
04-30 20:41:17.928: D/TrackList(13465): clearTrackIndexes
04-30 20:41:17.938: D/TrackList(13465): Add save tracklist addable
04-30 20:41:17.938: D/AsyncTaskManager(13465): Add exclusive addable
04-30 20:41:17.938: D/AsyncTaskManager(13465): Thread starting...
04-30 20:41:17.948: D/TrackList(13465): End of immediate addable: MediaAddable
04-30 20:41:17.948: D/AsyncTaskManager(13465): Task Polled
04-30 20:41:17.958: D/AsyncTaskManager(13465): Add addable
04-30 20:41:17.958: D/PlaybackService(13465): doPlayAction exit
04-30 20:41:17.958: D/PlaybackService(13465): stopDelayed idleDelay:180000 serviceInUse:false
04-30 20:41:17.958: D/PlaybackService(13465): onStartCommnad end in time 495
04-30 20:41:17.958: D/MiniPlayerActivity(13465): ACTION_USER_PRESENT unregisterReceiver
04-30 20:41:17.958: D/BaseActivity(13465): onPause com.ventismedia.android.mediamonkey.library.LibraryActivity
04-30 20:41:17.958: I/UIUtils(13465): setAppVisibility: false
04-30 20:41:17.968: D/ExtendedListFragment(13465): onPause com.ventismedia.android.mediamonkey.library.MediaFragment
04-30 20:41:17.988: D/BluetoothHeadset(13465): Proxy object connected
04-30 20:41:17.988: D/BluetoothHeadsetUtils(13465): Profile listener onServiceConnected
04-30 20:41:17.988: W/BluetoothHeadsetUtils(13465): no devices connected
04-30 20:41:17.988: D/AsyncTaskManager(13465): processTaskInner
04-30 20:41:17.998: D/AsyncTaskManager(13465): processTaskInner locked
04-30 20:41:17.998: E/MediaPlayer(13465): Should have subtitle controller already set
04-30 20:41:17.998: D/NowPlayingActivity(13465): onCreate
04-30 20:41:18.008: D/NowPlayingActivity(13465): onCreate uri: null
04-30 20:41:18.008: D/NowPlayingActivity(13465): onCreate has extra uri: false
04-30 20:41:18.008: D/BaseActivity(13465): onCreate com.ventismedia.android.mediamonkey.ui.phone.NowPlayingActivity
04-30 20:41:18.008: D/BaseActivity(13465): mUseLockScreenPlayer false
04-30 20:41:18.018: D/BaseActivity(13465): receiverRegistered false
04-30 20:41:18.018: D/TrialTimeUtils(13465): com.ventismedia.android.mediamonkey isProVersionInstalled: false signatureMatch:-3
04-30 20:41:18.018: D/TrialTimeUtils(13465): com.ventismedia.android.mediamonkey isProVersionInstalled: false signatureMatch:-3
04-30 20:41:18.058: I/SinglePaneActivity(13465): Add to backstack:false
04-30 20:41:18.078: D/TrackListManager(13465): Standard request
04-30 20:41:18.078: D/BaseActivity(13465): onStart com.ventismedia.android.mediamonkey.ui.phone.NowPlayingActivity
04-30 20:41:18.088: D/NowPlayingFragment(13465): onCreate
04-30 20:41:18.088: D/BaseFragment(13465): onCreate com.ventismedia.android.mediamonkey.player.NowPlayingFragment
04-30 20:41:18.088: D/TrackList(13465): Save tracklist addable...
04-30 20:41:18.088: D/TrackListModel(13465): 3601Store TrackList to preferences
04-30 20:41:18.098: V/WebViewChromium(13465): Binding Chromium to the main looper Looper (main, tid 1) {41ef65e0}
04-30 20:41:18.098: I/chromium(13465): [INFO:library_loader_hooks.cc(112)] Chromium logging enabled: level = 0, default verbosity = 0
04-30 20:41:18.098: I/BrowserProcessMain(13465): Initializing chromium process, renderers=0
04-30 20:41:18.098: D/TrackListModel(13465): storeCurrentTrack pos:0 list.size:1
04-30 20:41:18.108: D/TrackListModel(13465): storeCurrentTrackInfo: InfoTrack: [Untitled]-Lamb (Fear of Fours)
04-30 20:41:18.138: W/chromium(13465): [WARNING:proxy_service.cc(888)] PAC support disabled because there is no system implementation
04-30 20:41:18.248: D/BaseFragment(13465): onActivityCreated com.ventismedia.android.mediamonkey.player.NowPlayingFragment
04-30 20:41:18.248: D/NowPlayingFragment(13465): onActivityPostCreated
04-30 20:41:18.258: W/NowPlayingFragment(13465): LYRICS_AUTO_SEARCH false
04-30 20:41:18.258: W/NowPlayingFragment(13465): LYRICS_AUTO_SAVE false
04-30 20:41:18.258: W/NowPlayingFragment(13465): LYRICS_AUTO_SEARCH false
04-30 20:41:18.258: W/NowPlayingFragment(13465): LYRICS_AUTO_SAVE false
04-30 20:41:18.258: D/UIUtils(13465): isAppVisible: false
04-30 20:41:18.258: D/NowPlayingFragment(13465): onStart false
04-30 20:41:18.258: D/BaseFragment(13465): onStart com.ventismedia.android.mediamonkey.player.NowPlayingFragment
04-30 20:41:18.268: D/TrialTimeUtils(13465): com.ventismedia.android.mediamonkey isProVersionInstalled: false signatureMatch:-3
04-30 20:41:18.268: D/NowPlayingActivity(13465): Activity onPrepareOptionsMenu
04-30 20:41:18.268: D/NowPlayingFragment(13465): onPrepareOptionsMenu
04-30 20:41:18.288: D/BaseActivity(13465): onResume com.ventismedia.android.mediamonkey.ui.phone.NowPlayingActivity
04-30 20:41:18.288: D/UIUtils(13465): isAppVisible: false
04-30 20:41:18.288: I/UIUtils(13465): setAppVisibility: true
04-30 20:41:18.298: D/BaseActivity(13465): mUseLockScreenPlayer false
04-30 20:41:18.298: D/BaseActivity(13465): receiverRegistered false
04-30 20:41:18.298: D/BaseActivity(13465): mProAlreadyInstalled: false
04-30 20:41:18.298: D/BaseActivity(13465): mProAlreadyTested: true
04-30 20:41:18.308: D/NowPlayingActivity(13465): startMediaPlayback mimeType: null
04-30 20:41:18.308: D/NowPlayingActivity(13465): startMediaPlayback uri: null
04-30 20:41:18.308: D/NowPlayingActivity(13465): has no extra uri
04-30 20:41:18.308: D/Utils(13465): mimeType is null
04-30 20:41:18.308: D/Utils(13465): uri is null
04-30 20:41:18.308: D/NowPlayingActivity(13465): Switch, if actual track is video. Is video ? false
04-30 20:41:18.318: D/UIUtils(13465): isAppVisible: true
04-30 20:41:18.318: D/NowPlayingFragment(13465): onResume true isInKeyguardRestrictedInputMode:false
04-30 20:41:18.318: D/BaseFragment(13465): onResume com.ventismedia.android.mediamonkey.player.NowPlayingFragment
04-30 20:41:18.318: D/NowPlayingFragment(13465): want to bind service
04-30 20:41:18.318: D/NowPlayingFragment(13465): bind playback service
04-30 20:41:18.328: D/NowPlayingFragment(13465): Register Broadcast receiver
04-30 20:41:18.358: D/dalvikvm(13465): GC_FOR_ALLOC freed 1902K, 14% free 12085K/14024K, paused 34ms, total 34ms
04-30 20:41:18.358: D/NowPlayingFragment(13465): ACTION_USER_PRESENT registerReceiver
04-30 20:41:18.368: D/PlaybackService(13465): Intent command received
04-30 20:41:18.368: D/PlaybackService(13465): action:com.ventismedia.android.mediamonkey.player.PlaybackService.REFRESH_NOTIFICATION_ACTION
04-30 20:41:18.368: D/PlaybackService(13465): mIsDelayWidgetUpdate false
04-30 20:41:18.368: D/PlaybackService(13465): mIsKeyguardWidgetCommand false
04-30 20:41:18.378: D/PlaybackService(13465): Service is running
04-30 20:41:18.378: D/PlaybackService(13465): REFRESH_NOTIFICATION_ACTION:true
04-30 20:41:18.378: D/PlaybackService(13465): stopDelayed idleDelay:180000 serviceInUse:false
04-30 20:41:18.378: D/StorageObserverService(13465): APP_GO_TO_BACKGROUND received
04-30 20:41:18.378: D/MediaStoreSyncObserver(13465): App goes to background
04-30 20:41:18.378: D/PlaybackService(13465): Intent command received
04-30 20:41:18.378: D/PlaybackService(13465): action:com.ventismedia.android.mediamonkey.player.PlaybackService.REFRESH_NOTIFICATION_ACTION
04-30 20:41:18.378: D/PlaybackService(13465): mIsDelayWidgetUpdate false
04-30 20:41:18.388: D/PlaybackService(13465): mIsKeyguardWidgetCommand false
04-30 20:41:18.388: D/PlaybackService(13465): Service is running
04-30 20:41:18.388: D/PlaybackService(13465): REFRESH_NOTIFICATION_ACTION:true
04-30 20:41:18.388: D/PlaybackService(13465): stopDelayed idleDelay:180000 serviceInUse:false
04-30 20:41:18.388: D/StorageObserverService(13465): APP_GO_TO_FOREGROUND received
04-30 20:41:18.388: D/MediaStoreSyncObserver(13465): App goes to foreground
04-30 20:41:18.388: D/MediaStoreSyncObserver(13465): On wake up
04-30 20:41:18.388: D/SyncLauncher(13465): Application goes to foreground
04-30 20:41:18.388: I/StorageObserverService(13465): Service is running
04-30 20:41:18.388: D/BaseService(13465): onStartCommand com.ventismedia.android.mediamonkey.player.PlaybackService, intent:null, flags:0, startId:2
04-30 20:41:18.388: V/PlaybackService(13465): hidePasiveNotification
04-30 20:41:18.388: D/PlaybackService(13465): isBtHeadsetConnected false
04-30 20:41:18.388: D/PlaybackService(13465): mServiceStartId 2
04-30 20:41:18.398: D/PlaybackService(13465): createPlayer
04-30 20:41:18.398: D/PlaybackService(13465): Parsing intent null
04-30 20:41:18.398: D/PlaybackService(13465): Parsing intent mIsDelayWidgetUpdate false
04-30 20:41:18.398: D/PlaybackService(13465): Parsing intent mIsKeyguardWidgetCommand false
04-30 20:41:18.398: D/PlaybackService(13465): stopDelayed idleDelay:180000 serviceInUse:false
04-30 20:41:18.398: D/PlaybackService(13465): onStartCommnad end in time 6
04-30 20:41:18.398: D/PlaybackService(13465): onBind
04-30 20:41:18.408: D/NowPlayingFragment(13465): createLyricsLayout
04-30 20:41:18.488: D/NowPlayingFragment(13465): initLastLoadedViews()
04-30 20:41:18.488: W/ViewInitHelper(13465): TextView lyrics cannot be found in Now playing
04-30 20:41:18.488: W/ViewInitHelper(13465): TextView provided_by cannot be found in Now playing
04-30 20:41:18.498: W/ViewInitHelper(13465): Button lyrics_search_button cannot be found in Now playing
04-30 20:41:18.498: W/ViewInitHelper(13465): ProgressBar lyrics_search_progress cannot be found in Now playing
04-30 20:41:18.498: W/ViewInitHelper(13465): LinearLayout lyrics_buttons cannot be found in Now playing
04-30 20:41:18.498: W/ViewInitHelper(13465): Button lyrics_save_button cannot be found in Now playing
04-30 20:41:18.498: W/ViewInitHelper(13465): Button lyrics_clear_button cannot be found in Now playing
04-30 20:41:18.498: W/ViewInitHelper(13465): Button lyrics_search_alternate_button cannot be found in Now playing
04-30 20:41:18.498: W/ViewInitHelper(13465): Button lyrics_edit_button cannot be found in Now playing
04-30 20:41:18.508: W/ViewInitHelper(13465): ScrollView lyrics_scroll cannot be found in Now playing
04-30 20:41:18.508: D/NowPlayingSeekHelper(13465): NowPlayingSeekHelper constructor
04-30 20:41:18.508: D/NowPlayingFragment(13465): createLyricsLayout
04-30 20:41:18.528: D/NowPlayingFragment(13465): initLastLoadedViews()
04-30 20:41:18.528: D/NowPlayingSeekHelper(13465): NowPlayingSeekHelper constructor
04-30 20:41:18.578: D/TrackListModel(13465): TRACK_ 0saved
04-30 20:41:18.608: D/NowPlayingFragment 2(13465): onServiceConnected
04-30 20:41:18.618: I/AlbumArtSearcher(13465): autoSearch.
04-30 20:41:18.618: V/AbstractWebSearcher(13465): stopSearching
04-30 20:41:18.618: D/AlbumArtSearcher(13465): Auto search disabled
04-30 20:41:18.618: I/TrackList(13465): Weak OnTracklistChangeListener was added1
04-30 20:41:18.618: D/NowPlayingFragment(13465): REFRESH PREVIOUS TRACK INFO
04-30 20:41:18.618: W/TrackList(13465): Previous track Index is null, return
04-30 20:41:18.618: I/TrackList(13465): hasNextTrack
04-30 20:41:18.628: D/NowPlayingFragment(13465): updating view
04-30 20:41:18.658: D/dalvikvm(13465): GC_FOR_ALLOC freed 1156K, 12% free 12405K/14024K, paused 33ms, total 35ms
04-30 20:41:18.668: D/TrialTimeUtils(13465): com.ventismedia.android.mediamonkey isProVersionInstalled: false signatureMatch:-3
04-30 20:41:18.668: D/NowPlayingActivity(13465): Activity onPrepareOptionsMenu
04-30 20:41:18.668: D/NowPlayingFragment(13465): onPrepareOptionsMenu
04-30 20:41:18.708: D/PlaybackService(13465): updateWidgets tracklist is loaded
04-30 20:41:18.808: D/TrackListModel(13465): TrackList saved 1
04-30 20:41:18.858: D/AsyncTaskManager(13465): processTaskInner unlocking...
04-30 20:41:18.858: D/AsyncTaskManager(13465): processTaskInner unlock
04-30 20:41:18.858: D/AsyncTaskManager(13465): Task Polled
04-30 20:41:18.858: D/AsyncTaskManager(13465): processTaskInner
04-30 20:41:18.868: D/AsyncTaskManager(13465): processTaskInner locked
04-30 20:41:18.898: D/PlaybackService(13465): Intent command received
04-30 20:41:18.898: D/PlaybackService(13465): action:com.ventismedia.android.mediamonkey.player.PlaybackService.TRACK_LIST_SAVED
04-30 20:41:18.908: D/PlaybackService(13465): mIsDelayWidgetUpdate false
04-30 20:41:18.908: D/PlaybackService(13465): mIsKeyguardWidgetCommand false
04-30 20:41:18.908: D/PlaybackService(13465): updateWidgets immediately
04-30 20:41:18.908: D/PlaybackService(13465): updateWidgets tracklist is loaded
04-30 20:41:18.908: D/PlayerWidgetModel(13465): Loading widget Ids
04-30 20:41:18.908: W/PlaybackService(13465): updateRemotePlaybackState isPlaying:true
04-30 20:41:18.918: D/PlaybackService(13465): Delayed notification update
04-30 20:41:18.928: D/UIUtils(13465): isAppVisible: true
04-30 20:41:18.928: D/PlaybackService(13465): updateNotification app is : in foreground isInKeyguardRestrictedInputMode: false
04-30 20:41:18.928: D/UIUtils(13465): isAppVisible: true
04-30 20:41:18.928: D/PlaybackService(13465): T2 show notification when player is playing
04-30 20:41:18.928: D/PlaybackService(13465): showNotification is Playing: true playerState: PLAYING
04-30 20:41:18.928: D/PlaybackService(13465): mUseLockScreenPlayer false
04-30 20:41:18.928: D/PlaybackService(13465): receiverRegistered false
04-30 20:41:18.928: D/PlaybackService(13465): updateWidgets tracklist is loaded
04-30 20:41:18.928: I/TrackList(13465): hasNextTrack
04-30 20:41:18.938: I/BitmapUtils(13465): albumArt:file:///storage/emulated/0/Android/data/com.android.providers.media/albumthumbs/1381928440528
04-30 20:41:18.988: D/dalvikvm(13465): GC_FOR_ALLOC freed 679K, 11% free 12608K/14024K, paused 49ms, total 50ms
04-30 20:41:18.998: D/PlaybackNotification(13465): prepareStopButton
04-30 20:41:19.008: I/BitmapUtils(13465): albumArt:file:///storage/emulated/0/Android/data/com.android.providers.media/albumthumbs/1381928440528
04-30 20:41:19.048: D/dalvikvm(13465): GC_FOR_ALLOC freed 254K, 11% free 12688K/14128K, paused 36ms, total 37ms
04-30 20:41:19.048: I/dalvikvm-heap(13465): Grow heap (frag case) to 12.813MB for 409616-byte allocation
04-30 20:41:19.088: D/dalvikvm(13465): GC_FOR_ALLOC freed <1K, 10% free 13088K/14532K, paused 35ms, total 35ms
04-30 20:41:19.088: D/PlaybackNotification(13465): prepareStopButton
04-30 20:41:19.128: D/LibraryActivity(13465): onSaveInstanceState
04-30 20:41:19.128: D/BaseActivity(13465): onSaveInstanceState com.ventismedia.android.mediamonkey.library.LibraryActivity
04-30 20:41:19.128: D/ExtendedListFragment(13465): onSaveInstanceState com.ventismedia.android.mediamonkey.library.MediaFragment
04-30 20:41:19.128: D/BaseActivity(13465): onStop com.ventismedia.android.mediamonkey.library.LibraryActivity
04-30 20:41:19.128: D/ExtendedListFragment(13465): onStop com.ventismedia.android.mediamonkey.library.MediaFragment
04-30 20:41:19.148: D/TrackListManager(13465): Standard request
04-30 20:41:19.168: D/TrackList(13465): Start of async addable: MediaAddable
04-30 20:41:19.168: D/MediaAddable(13465): addAsync
04-30 20:41:19.308: D/dalvikvm(13465): GC_FOR_ALLOC freed 844K, 14% free 12521K/14532K, paused 38ms, total 39ms
04-30 20:41:19.308: D/MediaAddable(13465): TypeGroup: MUSIC
04-30 20:41:19.308: D/MediaAddable(13465): ShuffleAll: false
04-30 20:41:19.308: D/MediaAddable(13465): Add all: true
04-30 20:41:19.308: D/MediaAddable(13465): MediaId: 15
04-30 20:41:19.318: D/MediaAddable(13465): SkipCurrentTrack: true
04-30 20:41:19.318: D/TransactionManager 13(13465): ThreadSerializer is turning off, starting new one...
04-30 20:41:19.318: D/TransactionManager(13465): acquireWakeLock
04-30 20:41:19.318: W/TransactionManager(13465): New ThreadSerializer id from -1 to 3613
04-30 20:41:19.348: D/MediaMonkeyStoreProvider 1(13465): Query: /audio/media;Projection:[_id, title, _data, album, album_id, artists, track, year, _ms_id, duration, bookmark, playcount, skipcount, type, volume_leveling, album_art, rating, lyrics, mime_type, guid, idfolder];Selection:(type=?);Args:[0]
04-30 20:41:19.368: E/Provider(13465): Integrity check failed:
04-30 20:41:19.368: E/Provider(13465): rowid 1 missing from index media_title_type_idx
04-30 20:41:19.368: E/Provider(13465): rowid 7 missing from index media_title_type_idx
04-30 20:41:19.368: E/Provider(13465): rowid 13 missing from index media_title_type_idx
04-30 20:41:19.378: E/Provider(13465): rowid 15 missing from index media_title_type_idx
04-30 20:41:19.378: E/Provider(13465): rowid 20 missing from index media_title_type_idx
04-30 20:41:19.378: E/Provider(13465): rowid 23 missing from index media_title_type_idx
04-30 20:41:19.378: E/Provider(13465): rowid 3 missing from index album_name_type_idx
04-30 20:41:19.378: E/Provider(13465): rowid 4 missing from index album_name_type_idx
04-30 20:41:19.398: E/Provider(13465): Integrity check failed:
04-30 20:41:19.398: E/Provider(13465): rowid 1 missing from index media_title_type_idx
04-30 20:41:19.398: E/Provider(13465): rowid 7 missing from index media_title_type_idx
04-30 20:41:19.398: E/Provider(13465): rowid 13 missing from index media_title_type_idx
04-30 20:41:19.398: E/Provider(13465): rowid 15 missing from index media_title_type_idx
04-30 20:41:19.398: E/Provider(13465): rowid 20 missing from index media_title_type_idx
04-30 20:41:19.398: E/Provider(13465): rowid 23 missing from index media_title_type_idx
04-30 20:41:19.398: E/Provider(13465): rowid 3 missing from index album_name_type_idx
04-30 20:41:19.398: E/Provider(13465): rowid 4 missing from index album_name_type_idx
log02-publish.txt (53,605 bytes)
04-30 19:31:22.408: D/Provider(6616): Integrity check OK
04-30 19:31:22.418: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:22.418: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/00 01 Intro.mp3
04-30 19:31:22.418: D/MediaAddable(6616): Set current track immediatelly
04-30 19:31:22.418: D/TrackList 1(6616): addAsCurrentTrack t!=null?true
04-30 19:31:22.418: I/TrackList(6616): setCurrentTrack: AudioTrack storeToPreferences:false
04-30 19:31:22.418: D/TrackList(6616): clearTrackIndexes
04-30 19:31:22.418: D/TrackListModel(6616): SaveCurrentTrackInfo only
04-30 19:31:22.428: D/TrackListModel(6616): storeCurrentTrackInfo: InfoTrack: 00 01 Intro-Unknown artist (aaa BigFast)
04-30 19:31:22.458: D/dalvikvm(6616): GC_FOR_ALLOC freed 1219K, 13% free 11379K/13064K, paused 24ms, total 24ms
04-30 19:31:22.458: I/TrackListModel(6616): getCurrentTrackInfo
04-30 19:31:22.458: W/PlayerStateInformator(6616): No track si set as current!
04-30 19:31:22.458: D/PlaybackService(6616): onCurrentTrackChange
04-30 19:31:22.458: D/PlaybackService(6616): onCurrentTrackChange AudioTrack
04-30 19:31:22.458: D/PlaybackService(6616): play
04-30 19:31:22.458: W/PlaybackService(6616): gainAudioFocus()
04-30 19:31:22.468: W/PlaybackService(6616): registerMediaButtonEventReceiver on checkRemoteControlClientCompact
04-30 19:31:22.468: I/PlaybackService(6616): registerMediaButtonEventReceiver
04-30 19:31:22.468: D/PlaybackService(6616): mPlayer.setNormalVolume
04-30 19:31:22.468: D/PlaybackService(6616): Track can be played AudioTrack
04-30 19:31:22.478: D/TrackList(6616): playCurrentTrack
04-30 19:31:22.498: D/AudioPlayer(6616): setPlayerState to: PLAYING
04-30 19:31:22.508: D/AudioPlayer(6616): initTimePlayedInSession
04-30 19:31:22.508: D/PlaybackService(6616): enableEqualizerIfNeeded
04-30 19:31:22.508: D/EqualizerModel(6616): isEnabledEqualizer:false
04-30 19:31:22.508: D/PlaybackService(6616): updateRemoteMetadata(supported:true) - TrackInfo:00 01 Intro
04-30 19:31:22.508: W/PlaybackService(6616): updating RemoteControl state!
04-30 19:31:22.508: D/PlaybackService(6616): updateRemotePlaybackPosition
04-30 19:31:22.508: V/PlaybackService(6616): updateRemoteMetadata: 00 01 Intro
04-30 19:31:22.508: D/PlaybackService 3(6616): currentTrack.getAlbumArt: file:///storage/emulated/0/Android/data/com.android.providers.media/albumthumbs/1395672489216
04-30 19:31:22.538: D/dalvikvm(6616): GC_FOR_ALLOC freed 624K, 13% free 11402K/13064K, paused 23ms, total 23ms
04-30 19:31:22.538: I/dalvikvm-heap(6616): Grow heap (frag case) to 11.560MB for 412176-byte allocation
04-30 19:31:22.568: D/dalvikvm(6616): GC_FOR_ALLOC freed <1K, 13% free 11804K/13468K, paused 26ms, total 26ms
04-30 19:31:22.568: D/PlaybackService(6616): RemoteControlClientCompat available: true
04-30 19:31:22.568: D/PlaybackService(6616): albumArt width:320 height:322
04-30 19:31:22.568: D/PlaybackService 3(6616): currentTrack.getAlbumArt is not null true
04-30 19:31:22.578: I/PlaybackService(6616): refreshSuppressNotificationSounds
04-30 19:31:22.578: D/GlobalPreferences(6616): isSuppressNotificationSounds: false
04-30 19:31:22.578: D/UIUtils(6616): isAppVisible: true
04-30 19:31:22.578: D/PlaybackService(6616): updateNotification app is : in foreground isInKeyguardRestrictedInputMode: false
04-30 19:31:22.578: D/UIUtils(6616): isAppVisible: true
04-30 19:31:22.578: D/PlaybackService(6616): T2 show notification when player is playing
04-30 19:31:22.588: D/PlaybackService(6616): showNotification is Playing: true playerState: PLAYING
04-30 19:31:22.588: D/PlaybackService(6616): mUseLockScreenPlayer false
04-30 19:31:22.588: D/PlaybackService(6616): receiverRegistered false
04-30 19:31:22.588: D/PlaybackService(6616): updateWidgets tracklist is loaded
04-30 19:31:22.588: I/TrackList(6616): hasNextTrack
04-30 19:31:22.588: I/BitmapUtils(6616): albumArt:file:///storage/emulated/0/Android/data/com.android.providers.media/albumthumbs/1395672489216
04-30 19:31:22.618: D/dalvikvm(6616): GC_FOR_ALLOC freed 635K, 12% free 11892K/13468K, paused 25ms, total 25ms
04-30 19:31:22.618: I/dalvikvm-heap(6616): Grow heap (frag case) to 11.744MB for 103056-byte allocation
04-30 19:31:22.638: D/dalvikvm(6616): GC_FOR_ALLOC freed <1K, 12% free 11992K/13572K, paused 24ms, total 24ms
04-30 19:31:22.648: D/PlaybackNotification(6616): prepareStopButton
04-30 19:31:22.648: I/BitmapUtils(6616): albumArt:file:///storage/emulated/0/Android/data/com.android.providers.media/albumthumbs/1395672489216
04-30 19:31:22.678: D/dalvikvm(6616): GC_FOR_ALLOC freed 261K, 12% free 12018K/13572K, paused 25ms, total 25ms
04-30 19:31:22.678: I/dalvikvm-heap(6616): Grow heap (frag case) to 12.162MB for 412176-byte allocation
04-30 19:31:22.708: D/dalvikvm(6616): GC_FOR_ALLOC freed 16K, 12% free 12404K/13976K, paused 28ms, total 28ms
04-30 19:31:22.708: D/PlaybackNotification(6616): prepareStopButton
04-30 19:31:22.738: D/BroadcastSender 1(6616): SEND STATE_CHANGE_ACTION
04-30 19:31:22.748: D/TrackList(6616): Notify changes 1
04-30 19:31:22.748: D/TrackList(6616): clearTrackIndexes
04-30 19:31:22.748: D/TrackList(6616): Add save tracklist addable
04-30 19:31:22.758: D/AsyncTaskManager(6616): Add exclusive addable
04-30 19:31:22.758: D/AsyncTaskManager(6616): Thread starting...
04-30 19:31:22.768: D/TrackList(6616): End of immediate addable: MediaAddable
04-30 19:31:22.768: D/AsyncTaskManager(6616): Task Polled
04-30 19:31:22.768: D/AsyncTaskManager(6616): Add addable
04-30 19:31:22.768: D/PlaybackService(6616): doPlayAction exit
04-30 19:31:22.768: D/PlaybackService(6616): stopDelayed idleDelay:180000 serviceInUse:false
04-30 19:31:22.768: D/PlaybackService(6616): onStartCommnad end in time 658
04-30 19:31:22.768: D/AsyncTaskManager(6616): processTaskInner
04-30 19:31:22.768: D/AsyncTaskManager(6616): processTaskInner locked
04-30 19:31:22.768: D/TrackListManager(6616): Standard request
04-30 19:31:22.768: D/TrackList(6616): Save tracklist addable...
04-30 19:31:22.768: D/TrackListModel(6616): 3566Store TrackList to preferences
04-30 19:31:22.778: D/TrackListModel(6616): storeCurrentTrack pos:0 list.size:1
04-30 19:31:22.778: D/TrackListModel(6616): storeCurrentTrackInfo: InfoTrack: 00 01 Intro-Unknown artist (aaa BigFast)
04-30 19:31:22.778: D/TrackListModel(6616): TRACK_ 0saved
04-30 19:31:22.778: D/TrackListModel(6616): TrackList saved 1
04-30 19:31:22.938: D/AsyncTaskManager(6616): processTaskInner unlocking...
04-30 19:31:22.938: D/AsyncTaskManager(6616): processTaskInner unlock
04-30 19:31:22.938: D/AsyncTaskManager(6616): Task Polled
04-30 19:31:22.938: D/AsyncTaskManager(6616): processTaskInner
04-30 19:31:22.938: D/AsyncTaskManager(6616): processTaskInner locked
04-30 19:31:22.938: D/TrackListManager(6616): Standard request
04-30 19:31:22.938: D/TrackList(6616): Start of async addable: MediaAddable
04-30 19:31:22.938: D/MediaAddable(6616): addAsync
04-30 19:31:22.938: D/MediaAddable(6616): TypeGroup: MUSIC
04-30 19:31:22.948: D/MediaAddable(6616): ShuffleAll: false
04-30 19:31:22.948: D/MediaAddable(6616): Add all: true
04-30 19:31:22.948: D/MediaAddable(6616): MediaId: 10
04-30 19:31:22.948: D/MediaAddable(6616): SkipCurrentTrack: true
04-30 19:31:22.948: D/TransactionManager 13(6616): ThreadSerializer is turning off, starting new one...
04-30 19:31:22.948: D/MiniPlayerActivity(6616): ACTION_USER_PRESENT unregisterReceiver
04-30 19:31:22.948: D/BaseActivity(6616): onPause com.ventismedia.android.mediamonkey.library.LibraryActivity
04-30 19:31:22.948: D/TransactionManager(6616): acquireWakeLock
04-30 19:31:22.948: I/UIUtils(6616): setAppVisibility: false
04-30 19:31:22.948: W/TransactionManager(6616): New ThreadSerializer id from -1 to 3567
04-30 19:31:22.958: D/ExtendedListFragment(6616): onPause com.ventismedia.android.mediamonkey.library.MediaFragment
04-30 19:31:22.978: D/BluetoothHeadset(6616): Proxy object connected
04-30 19:31:22.978: D/BluetoothHeadsetUtils(6616): Profile listener onServiceConnected
04-30 19:31:22.988: W/BluetoothHeadsetUtils(6616): no devices connected
04-30 19:31:22.988: E/MediaPlayer(6616): Should have subtitle controller already set
04-30 19:31:22.988: D/NowPlayingActivity(6616): onCreate
04-30 19:31:22.998: D/NowPlayingActivity(6616): onCreate uri: null
04-30 19:31:22.998: D/NowPlayingActivity(6616): onCreate has extra uri: false
04-30 19:31:22.998: D/BaseActivity(6616): onCreate com.ventismedia.android.mediamonkey.ui.phone.NowPlayingActivity
04-30 19:31:22.998: D/BaseActivity(6616): mUseLockScreenPlayer false
04-30 19:31:22.998: D/BaseActivity(6616): receiverRegistered false
04-30 19:31:22.998: D/TrialTimeUtils(6616): com.ventismedia.android.mediamonkey isProVersionInstalled: false signatureMatch:-3
04-30 19:31:22.998: D/TrialTimeUtils(6616): com.ventismedia.android.mediamonkey isProVersionInstalled: false signatureMatch:-3
04-30 19:31:23.028: I/SinglePaneActivity(6616): Add to backstack:false
04-30 19:31:23.048: D/MediaMonkeyStoreProvider 1(6616): Query: /audio/media;Projection:[_id, title, _data, album, album_id, artists, track, year, _ms_id, duration, bookmark, playcount, skipcount, type, volume_leveling, album_art, rating, lyrics, mime_type, guid, idfolder];Selection:(type=?);Args:[0]
04-30 19:31:23.088: D/dalvikvm(6616): GC_FOR_ALLOC freed 2050K, 15% free 11934K/14020K, paused 34ms, total 34ms
04-30 19:31:23.088: D/BaseActivity(6616): onStart com.ventismedia.android.mediamonkey.ui.phone.NowPlayingActivity
04-30 19:31:23.088: D/NowPlayingFragment(6616): onCreate
04-30 19:31:23.088: D/BaseFragment(6616): onCreate com.ventismedia.android.mediamonkey.player.NowPlayingFragment
04-30 19:31:23.098: V/WebViewChromium(6616): Binding Chromium to the main looper Looper (main, tid 1) {41ef4560}
04-30 19:31:23.098: I/chromium(6616): [INFO:library_loader_hooks.cc(112)] Chromium logging enabled: level = 0, default verbosity = 0
04-30 19:31:23.098: I/BrowserProcessMain(6616): Initializing chromium process, renderers=0
04-30 19:31:23.118: W/chromium(6616): [WARNING:proxy_service.cc(888)] PAC support disabled because there is no system implementation
04-30 19:31:23.188: D/BaseFragment(6616): onActivityCreated com.ventismedia.android.mediamonkey.player.NowPlayingFragment
04-30 19:31:23.188: D/NowPlayingFragment(6616): onActivityPostCreated
04-30 19:31:23.188: W/NowPlayingFragment(6616): LYRICS_AUTO_SEARCH false
04-30 19:31:23.188: W/NowPlayingFragment(6616): LYRICS_AUTO_SAVE false
04-30 19:31:23.188: W/NowPlayingFragment(6616): LYRICS_AUTO_SEARCH false
04-30 19:31:23.188: W/NowPlayingFragment(6616): LYRICS_AUTO_SAVE false
04-30 19:31:23.198: D/UIUtils(6616): isAppVisible: false
04-30 19:31:23.198: D/NowPlayingFragment(6616): onStart false
04-30 19:31:23.198: D/BaseFragment(6616): onStart com.ventismedia.android.mediamonkey.player.NowPlayingFragment
04-30 19:31:23.198: D/TrialTimeUtils(6616): com.ventismedia.android.mediamonkey isProVersionInstalled: false signatureMatch:-3
04-30 19:31:23.208: D/NowPlayingActivity(6616): Activity onPrepareOptionsMenu
04-30 19:31:23.208: D/NowPlayingFragment(6616): onPrepareOptionsMenu
04-30 19:31:23.208: D/Provider(6616): Integrity check OK
04-30 19:31:23.228: D/BaseActivity(6616): onResume com.ventismedia.android.mediamonkey.ui.phone.NowPlayingActivity
04-30 19:31:23.228: D/UIUtils(6616): isAppVisible: false
04-30 19:31:23.228: I/UIUtils(6616): setAppVisibility: true
04-30 19:31:23.228: D/BaseActivity(6616): mUseLockScreenPlayer false
04-30 19:31:23.238: D/BaseActivity(6616): receiverRegistered false
04-30 19:31:23.238: D/BaseActivity(6616): mProAlreadyInstalled: false
04-30 19:31:23.238: D/BaseActivity(6616): mProAlreadyTested: true
04-30 19:31:23.238: D/NowPlayingActivity(6616): startMediaPlayback mimeType: null
04-30 19:31:23.238: D/NowPlayingActivity(6616): startMediaPlayback uri: null
04-30 19:31:23.238: D/NowPlayingActivity(6616): has no extra uri
04-30 19:31:23.238: D/Utils(6616): mimeType is null
04-30 19:31:23.238: D/Utils(6616): uri is null
04-30 19:31:23.238: D/NowPlayingActivity(6616): Switch, if actual track is video. Is video ? false
04-30 19:31:23.248: D/UIUtils(6616): isAppVisible: true
04-30 19:31:23.248: D/NowPlayingFragment(6616): onResume true isInKeyguardRestrictedInputMode:false
04-30 19:31:23.268: D/dalvikvm(6616): GC_FOR_ALLOC freed 1282K, 14% free 12073K/14020K, paused 26ms, total 26ms
04-30 19:31:23.278: D/BaseFragment(6616): onResume com.ventismedia.android.mediamonkey.player.NowPlayingFragment
04-30 19:31:23.278: D/NowPlayingFragment(6616): want to bind service
04-30 19:31:23.278: D/NowPlayingFragment(6616): bind playback service
04-30 19:31:23.278: D/NowPlayingFragment(6616): Register Broadcast receiver
04-30 19:31:23.278: D/NowPlayingFragment(6616): ACTION_USER_PRESENT registerReceiver
04-30 19:31:23.288: D/PlaybackService(6616): Intent command received
04-30 19:31:23.288: D/PlaybackService(6616): action:com.ventismedia.android.mediamonkey.player.PlaybackService.TRACK_LIST_SAVED
04-30 19:31:23.288: D/PlaybackService(6616): mIsDelayWidgetUpdate false
04-30 19:31:23.288: D/PlaybackService(6616): mIsKeyguardWidgetCommand false
04-30 19:31:23.288: D/PlaybackService(6616): updateWidgets immediately
04-30 19:31:23.288: D/PlaybackService(6616): updateWidgets tracklist is loaded
04-30 19:31:23.288: D/PlayerWidgetModel(6616): Loading widget Ids
04-30 19:31:23.288: W/PlaybackService(6616): updateRemotePlaybackState isPlaying:true
04-30 19:31:23.298: D/PlaybackService(6616): Intent command received
04-30 19:31:23.298: D/PlaybackService(6616): action:com.ventismedia.android.mediamonkey.player.PlaybackService.REFRESH_NOTIFICATION_ACTION
04-30 19:31:23.298: D/PlaybackService(6616): mIsDelayWidgetUpdate false
04-30 19:31:23.298: D/PlaybackService(6616): mIsKeyguardWidgetCommand false
04-30 19:31:23.298: D/PlaybackService(6616): Service is running
04-30 19:31:23.298: D/PlaybackService(6616): REFRESH_NOTIFICATION_ACTION:true
04-30 19:31:23.298: D/PlaybackService(6616): stopDelayed idleDelay:180000 serviceInUse:false
04-30 19:31:23.298: D/StorageObserverService(6616): APP_GO_TO_BACKGROUND received
04-30 19:31:23.298: D/MediaStoreSyncObserver(6616): App goes to background
04-30 19:31:23.298: D/PlaybackService(6616): Intent command received
04-30 19:31:23.298: D/PlaybackService(6616): action:com.ventismedia.android.mediamonkey.player.PlaybackService.REFRESH_NOTIFICATION_ACTION
04-30 19:31:23.308: D/PlaybackService(6616): mIsDelayWidgetUpdate false
04-30 19:31:23.308: D/PlaybackService(6616): mIsKeyguardWidgetCommand false
04-30 19:31:23.308: D/PlaybackService(6616): Service is running
04-30 19:31:23.308: D/PlaybackService(6616): REFRESH_NOTIFICATION_ACTION:true
04-30 19:31:23.308: D/PlaybackService(6616): stopDelayed idleDelay:180000 serviceInUse:false
04-30 19:31:23.308: D/StorageObserverService(6616): APP_GO_TO_FOREGROUND received
04-30 19:31:23.308: D/MediaStoreSyncObserver(6616): App goes to foreground
04-30 19:31:23.308: D/MediaStoreSyncObserver(6616): On wake up
04-30 19:31:23.308: D/SyncLauncher(6616): Application goes to foreground
04-30 19:31:23.308: I/StorageObserverService(6616): Service is running
04-30 19:31:23.308: D/BaseService(6616): onStartCommand com.ventismedia.android.mediamonkey.player.PlaybackService, intent:null, flags:0, startId:2
04-30 19:31:23.308: V/PlaybackService(6616): hidePasiveNotification
04-30 19:31:23.308: D/PlaybackService(6616): isBtHeadsetConnected false
04-30 19:31:23.308: D/PlaybackService(6616): mServiceStartId 2
04-30 19:31:23.308: D/PlaybackService(6616): createPlayer
04-30 19:31:23.308: D/PlaybackService(6616): Parsing intent null
04-30 19:31:23.318: D/PlaybackService(6616): Parsing intent mIsDelayWidgetUpdate false
04-30 19:31:23.318: D/PlaybackService(6616): Parsing intent mIsKeyguardWidgetCommand false
04-30 19:31:23.318: D/PlaybackService(6616): stopDelayed idleDelay:180000 serviceInUse:false
04-30 19:31:23.318: D/PlaybackService(6616): onStartCommnad end in time 7
04-30 19:31:23.348: D/dalvikvm(6616): GC_FOR_ALLOC freed 1467K, 14% free 12074K/14020K, paused 27ms, total 27ms
04-30 19:31:23.348: D/Provider(6616): Integrity check OK
04-30 19:31:23.348: D/PlaybackService(6616): onBind
04-30 19:31:23.358: D/NowPlayingFragment(6616): createLyricsLayout
04-30 19:31:23.368: D/TrackList 1(6616): addAll 42
04-30 19:31:23.368: D/TrackList 1(6616): addAll-currentItemId 10
04-30 19:31:23.368: D/TrackList 1(6616): perPartesInfo.addableIndex 0
04-30 19:31:23.378: D/TrackList 1(6616): found current track id at position3
04-30 19:31:23.378: D/TrackList 1(6616): addAll preCurrentList to begin
04-30 19:31:23.378: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.378: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/00 00 New Song01 pt18.mp3
04-30 19:31:23.378: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.378: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/04 [Untitled].mp3
04-30 19:31:23.378: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.378: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/01 (Intro).mp3
04-30 19:31:23.378: D/TrackList(6616): Notify changes 4
04-30 19:31:23.388: D/TrackList(6616): clearTrackIndexes
04-30 19:31:23.388: D/TrackList(6616): Add save tracklist addable
04-30 19:31:23.388: D/AsyncTaskManager(6616): Add exclusive addable
04-30 19:31:23.388: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.388: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/01 01 Unknown.mp3
04-30 19:31:23.388: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.388: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/01 Unknown.mp3
04-30 19:31:23.388: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.388: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/18 18 Unknown.mp3
04-30 19:31:23.398: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.398: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/18 Unknown.mp3
04-30 19:31:23.398: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.398: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/19 De-Sci-Fer.mp3
04-30 19:31:23.398: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.398: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/01 I Am X.mp3
04-30 19:31:23.408: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.408: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/09 Igor.mp3
04-30 19:31:23.438: D/dalvikvm(6616): GC_FOR_ALLOC freed 1186K, 12% free 12360K/14020K, paused 29ms, total 29ms
04-30 19:31:23.438: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.438: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/01 Intro.mp3
04-30 19:31:23.438: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.438: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/01 Intro (Mixed).mp3
04-30 19:31:23.438: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.448: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/01 Loading track.mp3
04-30 19:31:23.448: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.448: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/09 Mardo� Jede.mp3
04-30 19:31:23.448: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.448: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/19 Miracle Cure.mp3
04-30 19:31:23.448: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.448: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/09 Miss Underloops II..mp3
04-30 19:31:23.448: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.448: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/13 Miss Underloops III..mp3
04-30 19:31:23.458: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.458: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/14 monolog - o akordech a Pl�halovi.mp3
04-30 19:31:23.458: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.458: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/07 Mother Solar (Part One).mp3
04-30 19:31:23.458: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.458: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/00 New Song01 pt18.mp3
04-30 19:31:23.458: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.458: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/13 Normal Changing World.mp3
04-30 19:31:23.458: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.458: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/25 Pad� d횝, pad� d횝, vera bude leja.mp3
04-30 19:31:23.468: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.468: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/01 POP YEARMIX 2013.mp3
04-30 19:31:23.468: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.468: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/00 pusa.ogg
04-30 19:31:23.468: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.468: D/NowPlayingFragment(6616): initLastLoadedViews()
04-30 19:31:23.468: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/20 Untitled.mp3
04-30 19:31:23.468: W/ViewInitHelper(6616): TextView lyrics cannot be found in Now playing
04-30 19:31:23.468: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.468: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/30 Untitled Outtake 10.mp3
04-30 19:31:23.478: W/ViewInitHelper(6616): TextView provided_by cannot be found in Now playing
04-30 19:31:23.478: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.478: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/33 Untitled Outtake 13.mp3
04-30 19:31:23.478: W/ViewInitHelper(6616): Button lyrics_search_button cannot be found in Now playing
04-30 19:31:23.508: D/dalvikvm(6616): GC_FOR_ALLOC freed 1493K, 12% free 12432K/14020K, paused 28ms, total 28ms
04-30 19:31:23.508: W/ViewInitHelper(6616): ProgressBar lyrics_search_progress cannot be found in Now playing
04-30 19:31:23.508: W/ViewInitHelper(6616): LinearLayout lyrics_buttons cannot be found in Now playing
04-30 19:31:23.508: W/ViewInitHelper(6616): Button lyrics_save_button cannot be found in Now playing
04-30 19:31:23.508: W/ViewInitHelper(6616): Button lyrics_clear_button cannot be found in Now playing
04-30 19:31:23.508: W/ViewInitHelper(6616): Button lyrics_search_alternate_button cannot be found in Now playing
04-30 19:31:23.518: W/ViewInitHelper(6616): Button lyrics_edit_button cannot be found in Now playing
04-30 19:31:23.518: W/ViewInitHelper(6616): ScrollView lyrics_scroll cannot be found in Now playing
04-30 19:31:23.518: D/NowPlayingSeekHelper(6616): NowPlayingSeekHelper constructor
04-30 19:31:23.518: D/NowPlayingFragment(6616): createLyricsLayout
04-30 19:31:23.528: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.528: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/36 Untitled Outtake 16.mp3
04-30 19:31:23.528: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.528: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/37 Untitled Outtake 17.mp3
04-30 19:31:23.528: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.528: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/40 Untitled Outtake 20.mp3
04-30 19:31:23.528: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.528: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/41 Untitled Outtake 21.mp3
04-30 19:31:23.528: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.528: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/43 Untitled Outtake 23.mp3
04-30 19:31:23.528: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.538: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/44 Untitled Outtake 24.mp3
04-30 19:31:23.538: D/NowPlayingFragment(6616): initLastLoadedViews()
04-30 19:31:23.538: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.538: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/45 Untitled Outtake 25.mp3
04-30 19:31:23.538: D/NowPlayingSeekHelper(6616): NowPlayingSeekHelper constructor
04-30 19:31:23.538: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.538: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/47 Untitled Outtake 27.mp3
04-30 19:31:23.538: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.538: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/48 Untitled Outtake 28.mp3
04-30 19:31:23.548: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.548: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/24 Untitled Outtake 4.mp3
04-30 19:31:23.548: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.548: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/27 Untitled Outtake 7.mp3
04-30 19:31:23.558: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.558: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/28 Untitled Outtake 8.mp3
04-30 19:31:23.588: D/dalvikvm(6616): GC_FOR_ALLOC freed 1544K, 12% free 12472K/14052K, paused 29ms, total 30ms
04-30 19:31:23.588: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.588: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/29 Untitled Outtake 9.mp3
04-30 19:31:23.598: D/TrackFactory(6616): Get track instance for type: 0
04-30 19:31:23.598: D/AudioTrack(6616): PATH:/storage/emulated/0/Music/aaa BigFast/00 White Sand.mp3
04-30 19:31:23.598: D/TrackList(6616): Notify changes 42
04-30 19:31:23.598: D/TrackList(6616): clearTrackIndexes
04-30 19:31:23.598: D/TrackList(6616): Add save tracklist addable
04-30 19:31:23.598: D/AsyncTaskManager(6616): Add exclusive addable
04-30 19:31:23.598: D/TrackList(6616): End of async addable: MediaAddable
04-30 19:31:23.598: D/AsyncTaskManager(6616): processTaskInner unlocking...
04-30 19:31:23.598: D/AsyncTaskManager(6616): processTaskInner unlock
04-30 19:31:23.598: D/AsyncTaskManager(6616): Task Polled
04-30 19:31:23.598: D/AsyncTaskManager(6616): processTaskInner
04-30 19:31:23.598: D/AsyncTaskManager(6616): processTaskInner locked
04-30 19:31:23.598: D/TrackListManager(6616): Standard request
04-30 19:31:23.598: D/TrackList(6616): Save tracklist addable...
04-30 19:31:23.598: D/TrackListModel(6616): 3566Store TrackList to preferences
04-30 19:31:23.608: D/TrackListModel(6616): storeCurrentTrack pos:3 list.size:42
04-30 19:31:23.608: D/TrackListModel(6616): storeCurrentTrackInfo: InfoTrack: 00 01 Intro-Unknown artist (aaa BigFast)
04-30 19:31:23.608: D/TrackListModel(6616): TRACK_ 41saved
04-30 19:31:23.608: D/TrackListModel(6616): TrackList saved 42
04-30 19:31:23.618: D/AsyncTaskManager(6616): processTaskInner unlocking...
04-30 19:31:23.618: D/AsyncTaskManager(6616): processTaskInner unlock
04-30 19:31:23.658: D/NowPlayingFragment 2(6616): onServiceConnected
04-30 19:31:23.668: I/AlbumArtSearcher(6616): autoSearch.
04-30 19:31:23.668: V/AbstractWebSearcher(6616): stopSearching
04-30 19:31:23.668: D/AlbumArtSearcher(6616): Auto search disabled
04-30 19:31:23.668: I/TrackList(6616): Weak OnTracklistChangeListener was added1
04-30 19:31:23.668: D/NowPlayingFragment(6616): REFRESH PREVIOUS TRACK INFO
04-30 19:31:23.668: I/TrackList(6616): hasNextTrack
04-30 19:31:23.668: I/TrackList(6616): nextTrack
04-30 19:31:23.668: D/NowPlayingFragment(6616): updating view
04-30 19:31:23.678: D/TrialTimeUtils(6616): com.ventismedia.android.mediamonkey isProVersionInstalled: false signatureMatch:-3
04-30 19:31:23.678: D/NowPlayingActivity(6616): Activity onPrepareOptionsMenu
04-30 19:31:23.678: D/NowPlayingFragment(6616): onPrepareOptionsMenu
04-30 19:31:23.728: D/PlaybackService(6616): updateWidgets tracklist is loaded
04-30 19:31:23.758: D/dalvikvm(6616): GC_FOR_ALLOC freed 1488K, 11% free 12579K/14104K, paused 33ms, total 33ms
04-30 19:31:23.788: D/dalvikvm(6616): GC_FOR_ALLOC freed 44K, 11% free 12592K/14104K, paused 29ms, total 29ms
04-30 19:31:23.788: I/dalvikvm-heap(6616): Grow heap (frag case) to 12.722MB for 412176-byte allocation
04-30 19:31:23.818: D/dalvikvm(6616): GC_FOR_ALLOC freed <1K, 11% free 12994K/14508K, paused 27ms, total 27ms
04-30 19:31:23.858: D/PlaybackService(6616): Intent command received
04-30 19:31:23.858: D/PlaybackService(6616): action:com.ventismedia.android.mediamonkey.player.PlaybackService.TRACK_LIST_SAVED
04-30 19:31:23.868: D/PlaybackService(6616): mIsDelayWidgetUpdate false
04-30 19:31:23.868: D/PlaybackService(6616): mIsKeyguardWidgetCommand false
04-30 19:31:23.868: D/PlaybackService(6616): updateWidgets immediately
04-30 19:31:23.868: D/PlaybackService(6616): updateWidgets tracklist is loaded
04-30 19:31:23.868: D/PlayerWidgetModel(6616): Loading widget Ids
04-30 19:31:23.868: W/PlaybackService(6616): updateRemotePlaybackState isPlaying:true
04-30 19:31:23.878: D/PlaybackService(6616): Delayed notification update
04-30 19:31:23.878: D/UIUtils(6616): isAppVisible: true
04-30 19:31:23.888: D/PlaybackService(6616): updateNotification app is : in foreground isInKeyguardRestrictedInputMode: false
04-30 19:31:23.888: D/UIUtils(6616): isAppVisible: true
04-30 19:31:23.888: D/PlaybackService(6616): T2 show notification when player is playing
04-30 19:31:23.888: D/PlaybackService(6616): showNotification is Playing: true playerState: PLAYING
04-30 19:31:23.888: D/PlaybackService(6616): mUseLockScreenPlayer false
04-30 19:31:23.888: D/PlaybackService(6616): receiverRegistered false
04-30 19:31:23.888: D/PlaybackService(6616): updateWidgets tracklist is loaded
04-30 19:31:23.888: I/TrackList(6616): hasNextTrack
04-30 19:31:23.888: I/BitmapUtils(6616): albumArt:file:///storage/emulated/0/Android/data/com.android.providers.media/albumthumbs/1395672489216
04-30 19:31:23.898: D/PlaybackNotification(6616): prepareStopButton
04-30 19:31:23.898: I/BitmapUtils(6616): albumArt:file:///storage/emulated/0/Android/data/com.android.providers.media/albumthumbs/1395672489216
04-30 19:31:23.948: D/dalvikvm(6616): GC_FOR_ALLOC freed 879K, 12% free 13140K/14792K, paused 35ms, total 35ms
04-30 19:31:23.978: D/dalvikvm(6616): GC_FOR_ALLOC freed 71K, 11% free 13174K/14792K, paused 32ms, total 32ms
04-30 19:31:23.978: I/dalvikvm-heap(6616): Grow heap (frag case) to 13.291MB for 412176-byte allocation
04-30 19:31:24.018: D/dalvikvm(6616): GC_FOR_ALLOC freed 0K, 11% free 13577K/15196K, paused 39ms, total 39ms
04-30 19:31:24.028: D/PlaybackNotification(6616): prepareStopButton
04-30 19:31:24.368: D/LibraryActivity(6616): onSaveInstanceState
04-30 19:31:24.368: D/BaseActivity(6616): onSaveInstanceState com.ventismedia.android.mediamonkey.library.LibraryActivity
04-30 19:31:24.368: D/TransactionManager(6616): ThreadSerializer exiting
04-30 19:31:24.378: D/ExtendedListFragment(6616): onSaveInstanceState com.ventismedia.android.mediamonkey.library.MediaFragment
04-30 19:31:24.378: D/TransactionManager(6616): releaseWakeLock
04-30 19:31:24.378: D/BaseActivity(6616): onStop com.ventismedia.android.mediamonkey.library.LibraryActivity
04-30 19:31:24.378: I/TransactionManager(6616): ThreadSerializer exit
04-30 19:31:24.378: D/ExtendedListFragment(6616): onStop com.ventismedia.android.mediamonkey.library.MediaFragment
04-30 19:31:26.618: D/AsyncTaskManager(6616): Thread ending
04-30 19:31:39.418: D/PlaybackService(6616): onCompletion
04-30 19:31:39.428: D/PlaybackService(6616): currentPlayerPosition:16640
04-30 19:31:39.428: D/AudioPlayer(6616): isCompletion:true
04-30 19:31:39.428: D/AudioPlayer(6616): updateTimePlayedInSession from 0 LastCurrentPosition:16640 currentPosition:16640 mStartPosition:0
04-30 19:31:39.428: D/AudioPlayer(6616): old method increment:16640
04-30 19:31:39.428: D/AudioPlayer(6616): TPS updated: 16640
04-30 19:31:39.438: D/PlaybackService(6616): updatePlaycount
04-30 19:31:39.438: D/AudioPlayer(6616): isCompletion:true
04-30 19:31:39.438: D/AudioPlayer(6616): updateTimePlayedInSession from 16640 LastCurrentPosition:16640 currentPosition:16640 mStartPosition:16640
04-30 19:31:39.438: D/AudioPlayer(6616): old method increment:0
04-30 19:31:39.438: D/AudioPlayer(6616): TPS updated: 16640
04-30 19:31:39.448: D/MediaMonkeyStoreDbTrack(6616): calculateAndUpdatePlaycount:00 01 Intro
04-30 19:31:39.448: D/MediaMonkeyStoreDbTrack(6616): Track is shorter than 3 minutes, update playcount to ...1
04-30 19:31:39.448: V/TEST(6616): updateLoggedAsync last_time_played=1398879099 playcount=1
04-30 19:31:39.448: I/Dao(6616): Atomic operation start
04-30 19:31:39.448: D/TransactionManager(6616): UI thread is putting request to TM asynchronously!
04-30 19:31:39.458: D/TransactionManager 13(6616): ThreadSerializer is turning off, starting new one...
04-30 19:31:39.458: I/Dao(6616): Atomic operation end
04-30 19:31:39.458: D/PlaybackService(6616): TrackList is loaded.
04-30 19:31:39.458: D/PlaybackService(6616): nextTrack
04-30 19:31:39.468: I/TrackList(6616): nextTrack
04-30 19:31:39.468: D/TransactionManager(6616): acquireWakeLock
04-30 19:31:39.468: D/TrackList(6616): Current track position 3 tracklist size:42
04-30 19:31:39.468: I/TrackList(6616): setCurrentTrack: AudioTrack storeToPreferences:true
04-30 19:31:39.478: D/TrackList(6616): clearTrackIndexes
04-30 19:31:39.478: W/TransactionManager(6616): New ThreadSerializer id from -1 to 3580
04-30 19:31:39.478: D/TrackListModel(6616): Store current track to preferences: 01 Unknown-Unknown artist (Futuretro)
04-30 19:31:39.488: D/TrackListModel(6616): storeCurrentTrack pos:4 list.size:42
04-30 19:31:39.488: D/TrackListModel(6616): storeCurrentTrackInfo: InfoTrack: 01 Unknown-Unknown artist (Futuretro)
04-30 19:31:39.498: D/TrackListModel(6616): storeCurrentTrackInfo: InfoTrack: 01 Unknown-Unknown artist (Futuretro)
04-30 19:31:39.508: D/PlaybackService(6616): play
04-30 19:31:39.508: W/PlaybackService(6616): gainAudioFocus()
04-30 19:31:39.508: V/TEST(6616): Updating track
04-30 19:31:39.508: W/PlaybackService(6616): registerMediaButtonEventReceiver on checkRemoteControlClientCompact
04-30 19:31:39.508: D/AllMediaDao(6616): existsDirect?
04-30 19:31:39.508: I/PlaybackService(6616): registerMediaButtonEventReceiver
04-30 19:31:39.508: D/PlaybackService(6616): mPlayer.setNormalVolume
04-30 19:31:39.518: D/MediaMonkeyStoreProvider 1(6616): Query: /query;Projection:null;Selection:SELECT _ID FROM media WHERE _id=?;Args:[10]
04-30 19:31:39.518: D/PlaybackService(6616): Track can be played AudioTrack
04-30 19:31:39.518: D/TrackList(6616): playCurrentTrack
04-30 19:31:39.538: D/AudioPlayer(6616): setPlayerState to: PLAYING
04-30 19:31:39.538: D/AudioPlayer(6616): initTimePlayedInSession
04-30 19:31:39.538: D/PlaybackService(6616): enableEqualizerIfNeeded
04-30 19:31:39.538: D/EqualizerModel(6616): isEnabledEqualizer:false
04-30 19:31:39.548: D/PlaybackService(6616): updateRemoteMetadata(supported:true) - TrackInfo:01 Unknown
04-30 19:31:39.548: W/PlaybackService(6616): updating RemoteControl state!
04-30 19:31:39.548: D/PlaybackService(6616): updateRemotePlaybackPosition
04-30 19:31:39.548: V/PlaybackService(6616): updateRemoteMetadata: 01 Unknown
04-30 19:31:39.548: D/PlaybackService 3(6616): currentTrack.getAlbumArt: file:///storage/emulated/0/Android/data/com.android.providers.media/albumthumbs/1395672494905
04-30 19:31:39.598: D/dalvikvm(6616): GC_FOR_ALLOC freed 1909K, 15% free 13038K/15196K, paused 47ms, total 49ms
04-30 19:31:39.608: D/PlaybackService(6616): RemoteControlClientCompat available: true
04-30 19:31:39.608: D/PlaybackService(6616): albumArt width:320 height:320
04-30 19:31:39.608: D/PlaybackService 3(6616): currentTrack.getAlbumArt is not null true
04-30 19:31:39.618: D/PlaybackService(6616): updateWidgets immediately
04-30 19:31:39.618: D/PlaybackService(6616): updateWidgets tracklist is loaded
04-30 19:31:39.618: D/PlayerWidgetModel(6616): Loading widget Ids
04-30 19:31:39.618: W/PlaybackService(6616): updateRemotePlaybackState isPlaying:true
04-30 19:31:39.628: I/PlaybackService(6616): refreshSuppressNotificationSounds
04-30 19:31:39.628: D/GlobalPreferences(6616): isSuppressNotificationSounds: false
04-30 19:31:39.628: D/UIUtils(6616): isAppVisible: true
04-30 19:31:39.628: D/PlaybackService(6616): updateNotification app is : in foreground isInKeyguardRestrictedInputMode: false
04-30 19:31:39.638: D/UIUtils(6616): isAppVisible: true
04-30 19:31:39.638: D/PlaybackService(6616): T2 show notification when player is playing
04-30 19:31:39.638: D/PlaybackService(6616): showNotification is Playing: true playerState: PLAYING
04-30 19:31:39.638: D/PlaybackService(6616): mUseLockScreenPlayer false
04-30 19:31:39.638: D/PlaybackService(6616): receiverRegistered false
04-30 19:31:39.638: D/PlaybackService(6616): updateWidgets tracklist is loaded
04-30 19:31:39.638: I/TrackList(6616): hasNextTrack
04-30 19:31:39.638: I/BitmapUtils(6616): albumArt:file:///storage/emulated/0/Android/data/com.android.providers.media/albumthumbs/1395672494905
04-30 19:31:39.648: D/PlaybackNotification(6616): prepareStopButton
04-30 19:31:39.648: I/BitmapUtils(6616): albumArt:file:///storage/emulated/0/Android/data/com.android.providers.media/albumthumbs/1395672494905
04-30 19:31:39.688: D/dalvikvm(6616): GC_FOR_ALLOC freed 1058K, 14% free 13144K/15196K, paused 28ms, total 28ms
04-30 19:31:39.688: D/PlaybackNotification(6616): prepareStopButton
04-30 19:31:39.708: D/Provider(6616): Integrity check OK
04-30 19:31:39.718: D/DIRECT QUERY(6616): SELECT _ID FROM media WHERE _id=?
04-30 19:31:39.718: D/DIRECT QUERY(6616): [10]
04-30 19:31:39.798: D/PlaybackService(6616): updateWidgets immediately
04-30 19:31:39.798: D/PlaybackService(6616): updateWidgets tracklist is loaded
04-30 19:31:39.798: D/PlayerWidgetModel(6616): Loading widget Ids
04-30 19:31:39.798: W/PlaybackService(6616): updateRemotePlaybackState isPlaying:true
04-30 19:31:39.798: D/BroadcastSender 1(6616): SEND STATE_CHANGE_ACTION
04-30 19:31:39.808: D/BroadcastSender 1(6616): SEND NEXT_TRACK_START_ACTION is video ?false
04-30 19:31:39.808: D/PlaybackService(6616): onCompletion end
04-30 19:31:39.808: D/MediaStoreSyncService(6616): Service is not running
04-30 19:31:39.808: D/StorageObserverService(6616): Publish database event received.
04-30 19:31:39.808: E/MediaPlayer(6616): Should have subtitle controller already set
04-30 19:31:39.808: D/NowPlayingFragment(6616): Intent command received
04-30 19:31:39.808: D/NowPlayingFragment(6616): RECEIVE - STATE_CHANGE_ACTION
04-30 19:31:39.808: D/NowPlayingFragment(6616): REFRESH PREVIOUS TRACK INFO
04-30 19:31:39.808: I/TrackList(6616): hasNextTrack
04-30 19:31:39.818: I/TrackList(6616): nextTrack
04-30 19:31:39.818: D/NowPlayingFragment(6616): updating view
04-30 19:31:39.818: D/TrialTimeUtils(6616): com.ventismedia.android.mediamonkey isProVersionInstalled: false signatureMatch:-3
04-30 19:31:39.818: D/NowPlayingActivity(6616): Activity onPrepareOptionsMenu
04-30 19:31:39.818: D/NowPlayingFragment(6616): onPrepareOptionsMenu
04-30 19:31:39.848: D/PlaybackService(6616): updateWidgets tracklist is loaded
04-30 19:31:39.858: D/NowPlayingFragment(6616): Intent command received
04-30 19:31:39.858: D/NowPlayingFragment(6616): RECEIVE - NEXT_TRACK_START_ACTION
04-30 19:31:39.878: D/dalvikvm(6616): GC_FOR_ALLOC freed 1276K, 15% free 13024K/15196K, paused 26ms, total 26ms
04-30 19:31:39.888: V/LyricsSearcher(6616): stopSearching
04-30 19:31:39.888: I/AlbumArtSearcher(6616): autoSearch.
04-30 19:31:39.888: V/AbstractWebSearcher(6616): stopSearching
04-30 19:31:39.888: D/AlbumArtSearcher(6616): Auto search disabled
04-30 19:31:39.888: D/NowPlayingFragment(6616): REFRESH PREVIOUS TRACK INFO
04-30 19:31:39.888: D/NowPlayingFragment(6616): updating view
04-30 19:31:39.888: D/TrialTimeUtils(6616): com.ventismedia.android.mediamonkey isProVersionInstalled: false signatureMatch:-3
04-30 19:31:39.888: D/NowPlayingActivity(6616): Activity onPrepareOptionsMenu
04-30 19:31:39.898: D/NowPlayingFragment(6616): onPrepareOptionsMenu
04-30 19:31:39.908: D/Provider(6616): Integrity check OK
04-30 19:31:39.908: V/TEST(6616): Updating track with values:last_time_played=1398879099 playcount=1
04-30 19:31:39.908: D/MediaMonkeyStoreProvider 1(6616): Update: /async/audio/media/10/log,Values:last_time_played=1398879099 playcount=1,Selection:null, Args:null
04-30 19:31:39.928: D/PlaybackService(6616): updateWidgets tracklist is loaded
04-30 19:31:40.018: D/Provider(6616): Integrity check OK
04-30 19:31:40.018: D/MediaProvider(6616): Update media: 10 to last_time_played=1398879099 playcount=1
04-30 19:31:40.018: D/ModificationProvider(6616): Insert modification for media: 10
04-30 19:31:40.018: D/ModificationProvider(6616): Store string modification
04-30 19:31:40.018: D/ModificationProvider(6616): last_time_played oldValue: newValue:2014-04-30 17:31:39
04-30 19:31:40.038: D/ModificationProvider(6616): Store long modification
04-30 19:31:40.038: D/ModificationProvider(6616): playcount oldValue:0 newValue:1
04-30 19:31:40.158: D/Provider(6616): Integrity check OK
04-30 19:31:41.158: D/TransactionManager(6616): ThreadSerializer exiting
04-30 19:31:41.158: D/TransactionManager(6616): releaseWakeLock
04-30 19:31:41.158: I/TransactionManager(6616): ThreadSerializer exit
04-30 19:31:49.808: D/StorageObserverService(6616): Stop observers
04-30 19:31:49.808: D/MediaStoreSyncObserver(6616): Stop
04-30 19:31:49.818: D/StorageObserverService(6616): DelayedDatabaseCopyHandler: Call PublishDatabase start
04-30 19:31:49.818: D/RemoteDatabaseObserver(6616): Storage event: 32768 - null
04-30 19:31:49.818: D/MediaMonkeyStoreProvider 1(6616): Insert: /publish_database,Values:null
04-30 19:31:49.828: I/TransactionManager(6616): PublishDatabase put OperationRequest
04-30 19:31:49.828: W/TransactionManager(6616): UI thread is putting request to TM!
04-30 19:31:49.828: W/TransactionManager(6616): at dalvik.system.VMStack.getThreadStackTrace(Native Method)
04-30 19:31:49.828: W/TransactionManager(6616): at java.lang.Thread.getStackTrace(Thread.java:579)
04-30 19:31:49.828: W/TransactionManager(6616): at com.ventismedia.android.mediamonkey.db.TransactionManager$Request.<init>(TransactionManager.java:693)
04-30 19:31:49.828: W/TransactionManager(6616): at com.ventismedia.android.mediamonkey.db.TransactionManager$OperationRequest.<init>(TransactionManager.java:640)
04-30 19:31:49.828: W/TransactionManager(6616): at com.ventismedia.android.mediamonkey.db.TransactionManager$OperationRequest.<init>(TransactionManager.java:658)
04-30 19:31:49.838: W/TransactionManager(6616): at com.ventismedia.android.mediamonkey.db.TransactionManager.publishDatabase(TransactionManager.java:2013)
04-30 19:31:49.838: W/TransactionManager(6616): at com.ventismedia.android.mediamonkey.db.MediaMonkeyStoreProvider.insert(MediaMonkeyStoreProvider.java:502)
04-30 19:31:49.838: W/TransactionManager(6616): at android.content.ContentProvider$Transport.insert(ContentProvider.java:220)
04-30 19:31:49.838: W/TransactionManager(6616): at android.content.ContentResolver.insert(ContentResolver.java:1190)
04-30 19:31:49.868: D/dalvikvm(6616): GC_FOR_ALLOC freed 1403K, 12% free 13407K/15196K, paused 29ms, total 30ms
04-30 19:31:49.868: W/TransactionManager(6616): at com.ventismedia.android.mediamonkey.db.dao.Dao.publishDatabase(Dao.java:316)
04-30 19:31:49.878: W/TransactionManager(6616): at com.ventismedia.android.mediamonkey.db.dao.Dao.publishDatabase(Dao.java:305)
04-30 19:31:49.878: W/TransactionManager(6616): at com.ventismedia.android.mediamonkey.storage.StorageObserverService$DelayedDatabaseCopyHandler.handleMessage(StorageObserverService.java:120)
04-30 19:31:49.878: W/TransactionManager(6616): at android.os.Handler.dispatchMessage(Handler.java:102)
04-30 19:31:49.878: W/TransactionManager(6616): at android.os.Looper.loop(Looper.java:136)
04-30 19:31:49.878: W/TransactionManager(6616): at android.app.ActivityThread.main(ActivityThread.java:5017)
04-30 19:31:49.878: W/TransactionManager(6616): at java.lang.reflect.Method.invokeNative(Native Method)
04-30 19:31:49.878: W/TransactionManager(6616): at java.lang.reflect.Method.invoke(Method.java:515)
04-30 19:31:49.878: W/TransactionManager(6616): at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:779)
04-30 19:31:49.878: W/TransactionManager(6616): at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:595)
04-30 19:31:49.878: W/TransactionManager(6616): at dalvik.system.NativeStart.main(Native Method)
04-30 19:31:49.878: D/TransactionManager 13(6616): ThreadSerializer is turning off, starting new one...
04-30 19:31:49.888: D/StorageObserverService(6616): DelayedDatabaseCopyHandler: Call PublishDatabase end
04-30 19:31:49.888: D/TransactionManager(6616): acquireWakeLock
04-30 19:31:49.888: D/StorageObserverService(6616): Start observers
04-30 19:31:49.888: D/MediaStoreSyncObserver(6616): Start
04-30 19:31:49.888: W/TransactionManager(6616): New ThreadSerializer id from -1 to 3585
04-30 19:31:49.888: I/TransactionManager(6616): Command: PublishDatabase
04-30 19:31:49.908: D/ExternalSQLiteOpenHelper(6616): Checkpoint result:0,4,4
04-30 19:31:49.908: D/DbUtils(6616): Creating DB copy
04-30 19:31:49.908: D/DbUtils(6616): isMainStorageAvailable? true
04-30 19:31:49.918: W/StorageUtils(6616): Delete file: /storage/emulated/0/MediaMonkey/files/mmstore.db-wal
04-30 19:31:49.918: W/StorageUtils(6616): Delete file: /storage/emulated/0/MediaMonkey/files/mmstore.db-shm
04-30 19:31:49.918: W/StorageUtils(6616): Delete file: /storage/emulated/0/MediaMonkey/files/mmstore.db-journal
04-30 19:31:49.918: W/StorageUtils(6616): Delete file: /storage/emulated/0/MediaMonkey/files/mmstore.db
04-30 19:31:49.918: D/RemoteDatabaseObserver(6616): Storage event: DELETE - mmstore.db
04-30 19:31:49.918: W/FilesMsDao(6616): Delete file from MediaStore: /storage/emulated/0/MediaMonkey/files/mmstore.db
04-30 19:31:49.938: D/StorageUtils(6616): Scan files: [/storage/emulated/0/MediaMonkey/files]
04-30 19:31:49.948: D/RemoteDatabaseObserver(6616): Storage event: CREATE - mmstore.db
04-30 19:31:49.948: D/RemoteDatabaseObserver(6616): Storage event: OPEN - mmstore.db
04-30 19:31:49.958: D/RemoteDatabaseObserver(6616): Storage event: MODIFY - mmstore.db
04-30 19:31:49.958: D/RemoteDatabaseObserver(6616): Storage event: CLOSE WRITE - mmstore.db
04-30 19:31:49.958: D/DbUtils(6616): DB copy created
04-30 19:31:49.958: D/StorageUtils(6616): Scan files: [/storage/emulated/0/MediaMonkey/files/mmstore.db]
04-30 19:31:50.268: D/StorageUtils(6616): Scanned /storage/emulated/0/MediaMonkey/files/mmstore.db, uri=content://media/external/file/17003
04-30 19:31:50.558: D/StorageUtils(6616): Scanned /storage/emulated/0/MediaMonkey/files, uri=content://media/external/file/2907
04-30 19:31:50.968: D/TransactionManager(6616): ThreadSerializer exiting
04-30 19:31:50.968: D/TransactionManager(6616): releaseWakeLock
04-30 19:31:50.968: I/TransactionManager(6616): ThreadSerializer exit
04-30 19:31:54.888: D/PlaybackService(6616): onCompletion
04-30 19:31:54.898: D/PlaybackService(6616): currentPlayerPosition:15099
04-30 19:31:54.908: D/AudioPlayer(6616): isCompletion:true
04-30 19:31:54.908: D/AudioPlayer(6616): updateTimePlayedInSession from 0 LastCurrentPosition:15099 currentPosition:15099 mStartPosition:0
04-30 19:31:54.908: D/AudioPlayer(6616): old method increment:15099
04-30 19:31:54.908: D/AudioPlayer(6616): TPS updated: 15099
04-30 19:31:54.908: D/PlaybackService(6616): updatePlaycount
04-30 19:31:54.908: D/AudioPlayer(6616): isCompletion:true
04-30 19:31:54.918: D/AudioPlayer(6616): updateTimePlayedInSession from 15099 LastCurrentPosition:15099 currentPosition:15099 mStartPosition:15099
04-30 19:31:54.918: D/AudioPlayer(6616): old method increment:0
04-30 19:31:54.918: D/AudioPlayer(6616): TPS updated: 15099
04-30 19:31:54.918: D/MediaMonkeyStoreDbTrack(6616): calculateAndUpdatePlaycount:01 Unknown
04-30 19:31:54.918: D/MediaMonkeyStoreDbTrack(6616): Track is shorter than 3 minutes, update playcount to ...1
04-30 19:31:54.918: V/TEST(6616): updateLoggedAsync last_time_played=1398879114 playcount=1
04-30 19:31:54.918: I/Dao(6616): Atomic operation start
04-30 19:31:54.918: D/TransactionManager(6616): UI thread is putting request to TM asynchronously!
04-30 19:31:54.918: D/TransactionManager 13(6616): ThreadSerializer is turning off, starting new one...
04-30 19:31:54.918: I/Dao(6616): Atomic operation end
04-30 19:31:54.918: D/PlaybackService(6616): TrackList is loaded.
04-30 19:31:54.928: D/PlaybackService(6616): nextTrack
04-30 19:31:54.928: D/TransactionManager(6616): acquireWakeLock
04-30 19:31:54.928: W/TransactionManager(6616): New ThreadSerializer id from -1 to 3587
04-30 19:31:54.928: I/TrackList(6616): nextTrack
04-30 19:31:54.928: D/TrackList(6616): Current track position 4 tracklist size:42
04-30 19:31:54.928: I/TrackList(6616): setCurrentTrack: AudioTrack storeToPreferences:true
04-30 19:31:54.928: D/TrackList(6616): clearTrackIndexes
04-30 19:31:54.928: D/TrackListModel(6616): Store current track to preferences: 01 Unknown-Unknown artist (Futuretro)
04-30 19:31:54.928: D/TrackListModel(6616): storeCurrentTrack pos:5 list.size:42
04-30 19:31:54.938: D/TrackListModel(6616): storeCurrentTrackInfo: InfoTrack: 01 Unknown-Unknown artist (Futuretro)
04-30 19:31:54.938: D/TrackListModel(6616): storeCurrentTrackInfo: InfoTrack: 01 Unknown-Unknown artist (Futuretro)
04-30 19:31:54.948: D/PlaybackService(6616): play
04-30 19:31:54.948: W/PlaybackService(6616): gainAudioFocus()
04-30 19:31:54.948: W/PlaybackService(6616): registerMediaButtonEventReceiver on checkRemoteControlClientCompact
04-30 19:31:54.948: I/PlaybackService(6616): registerMediaButtonEventReceiver
04-30 19:31:54.958: V/TEST(6616): Updating track
04-30 19:31:54.958: D/AllMediaDao(6616): existsDirect?
04-30 19:31:54.958: D/MediaMonkeyStoreProvider 1(6616): Query: /query;Projection:null;Selection:SELECT _ID FROM media WHERE _id=?;Args:[16]
04-30 19:31:54.968: D/PlaybackService(6616): mPlayer.setNormalVolume
04-30 19:31:54.968: D/PlaybackService(6616): Track can be played AudioTrack
04-30 19:31:54.968: D/TrackList(6616): playCurrentTrack
04-30 19:31:54.988: D/AudioPlayer(6616): setPlayerState to: PLAYING
04-30 19:31:54.998: D/AudioPlayer(6616): initTimePlayedInSession
04-30 19:31:54.998: D/PlaybackService(6616): enableEqualizerIfNeeded
04-30 19:31:54.998: D/EqualizerModel(6616): isEnabledEqualizer:false
04-30 19:31:54.998: D/PlaybackService(6616): updateRemoteMetadata(supported:true) - TrackInfo:01 Unknown
04-30 19:31:54.998: W/PlaybackService(6616): updating RemoteControl state!
04-30 19:31:54.998: D/PlaybackService(6616): updateRemotePlaybackPosition
04-30 19:31:55.008: V/PlaybackService(6616): updateRemoteMetadata: 01 Unknown
04-30 19:31:55.008: D/PlaybackService 3(6616): currentTrack.getAlbumArt: file:///storage/emulated/0/Android/data/com.android.providers.media/albumthumbs/1395672494905
04-30 19:31:55.038: D/dalvikvm(6616): GC_FOR_ALLOC freed 1908K, 13% free 13395K/15344K, paused 34ms, total 34ms
04-30 19:31:55.068: D/dalvikvm(6616): GC_FOR_ALLOC freed 34K, 13% free 13394K/15344K, paused 27ms, total 27ms
04-30 19:31:55.078: I/dalvikvm-heap(6616): Grow heap (frag case) to 13.502MB for 409616-byte allocation
04-30 19:31:55.098: D/dalvikvm(6616): GC_FOR_ALLOC freed <1K, 13% free 13794K/15748K, paused 27ms, total 27ms
04-30 19:31:55.098: E/Provider(6616): Integrity check failed:
04-30 19:31:55.098: E/Provider(6616): rowid 2 missing from index playlist_data_idx
04-30 19:31:55.108: E/Provider(6616): rowid 2 missing from index sqlite_autoindex_playlists_1
04-30 19:31:55.108: E/Provider(6616): rowid 1 missing from index media_title_type_idx
04-30 19:31:55.108: E/Provider(6616): rowid 7 missing from index media_title_type_idx
04-30 19:31:55.108: E/Provider(6616): rowid 13 missing from index media_title_type_idx
04-30 19:31:55.108: D/PlaybackService(6616): RemoteControlClientCompat available: true
04-30 19:31:55.108: E/Provider(6616): rowid 15 missing from index media_title_type_idx
04-30 19:31:55.108: D/PlaybackService(6616): albumArt width:320 height:320
04-30 19:31:55.108: D/PlaybackService 3(6616): currentTrack.getAlbumArt is not null true
04-30 19:31:55.108: E/Provider(6616): rowid 20 missing from index media_title_type_idx
04-30 19:31:55.118: E/Provider(6616): rowid 23 missing from index media_title_type_idx
04-30 19:31:55.118: D/PlaybackService(6616): updateWidgets immediately
04-30 19:31:55.118: E/Provider(6616): rowid 3 missing from index album_name_type_idx
04-30 19:31:55.118: D/PlaybackService(6616): updateWidgets tracklist is loaded
04-30 19:31:55.118: E/Provider(6616): rowid 4 missing from index album_name_type_idx
log03-best publish.txt (15,117 bytes)
04-30 20:02:52.538: D/Provider(8030): Integrity check OK 04-30 20:02:52.568: D/dalvikvm(8030): GC_FOR_ALLOC freed 1886K, 18% free 13019K/15752K, paused 29ms, total 29ms 04-30 20:02:53.568: D/TransactionManager(8030): ThreadSerializer exiting 04-30 20:02:53.568: D/TransactionManager(8030): releaseWakeLock 04-30 20:02:53.578: I/TransactionManager(8030): ThreadSerializer exit 04-30 20:03:01.868: D/StorageObserverService(8030): Stop observers 04-30 20:03:01.868: D/MediaStoreSyncObserver(8030): Stop 04-30 20:03:01.868: D/StorageObserverService(8030): DelayedDatabaseCopyHandler: Call PublishDatabase start 04-30 20:03:01.868: D/RemoteDatabaseObserver(8030): Storage event: 32768 - null 04-30 20:03:01.878: D/MediaMonkeyStoreProvider 1(8030): Insert: /publish_database,Values:null 04-30 20:03:01.878: I/TransactionManager(8030): PublishDatabase put OperationRequest 04-30 20:03:01.878: W/TransactionManager(8030): UI thread is putting request to TM! 04-30 20:03:01.878: W/TransactionManager(8030): at dalvik.system.VMStack.getThreadStackTrace(Native Method) 04-30 20:03:01.878: W/TransactionManager(8030): at java.lang.Thread.getStackTrace(Thread.java:579) 04-30 20:03:01.888: W/TransactionManager(8030): at com.ventismedia.android.mediamonkey.db.TransactionManager$Request.<init>(TransactionManager.java:693) 04-30 20:03:01.888: W/TransactionManager(8030): at com.ventismedia.android.mediamonkey.db.TransactionManager$OperationRequest.<init>(TransactionManager.java:640) 04-30 20:03:01.888: W/TransactionManager(8030): at com.ventismedia.android.mediamonkey.db.TransactionManager$OperationRequest.<init>(TransactionManager.java:658) 04-30 20:03:01.888: W/TransactionManager(8030): at com.ventismedia.android.mediamonkey.db.TransactionManager.publishDatabase(TransactionManager.java:2013) 04-30 20:03:01.898: W/TransactionManager(8030): at com.ventismedia.android.mediamonkey.db.MediaMonkeyStoreProvider.insert(MediaMonkeyStoreProvider.java:502) 04-30 20:03:01.898: W/TransactionManager(8030): at android.content.ContentProvider$Transport.insert(ContentProvider.java:220) 04-30 20:03:01.898: W/TransactionManager(8030): at android.content.ContentResolver.insert(ContentResolver.java:1190) 04-30 20:03:01.898: W/TransactionManager(8030): at com.ventismedia.android.mediamonkey.db.dao.Dao.publishDatabase(Dao.java:316) 04-30 20:03:01.898: W/TransactionManager(8030): at com.ventismedia.android.mediamonkey.db.dao.Dao.publishDatabase(Dao.java:305) 04-30 20:03:01.908: W/TransactionManager(8030): at com.ventismedia.android.mediamonkey.storage.StorageObserverService$DelayedDatabaseCopyHandler.handleMessage(StorageObserverService.java:120) 04-30 20:03:01.908: W/TransactionManager(8030): at android.os.Handler.dispatchMessage(Handler.java:102) 04-30 20:03:01.908: W/TransactionManager(8030): at android.os.Looper.loop(Looper.java:136) 04-30 20:03:01.908: W/TransactionManager(8030): at android.app.ActivityThread.main(ActivityThread.java:5017) 04-30 20:03:01.908: W/TransactionManager(8030): at java.lang.reflect.Method.invokeNative(Native Method) 04-30 20:03:01.908: W/TransactionManager(8030): at java.lang.reflect.Method.invoke(Method.java:515) 04-30 20:03:01.918: W/TransactionManager(8030): at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:779) 04-30 20:03:01.918: W/TransactionManager(8030): at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:595) 04-30 20:03:01.918: W/TransactionManager(8030): at dalvik.system.NativeStart.main(Native Method) 04-30 20:03:01.918: D/TransactionManager 13(8030): ThreadSerializer is turning off, starting new one... 04-30 20:03:01.928: D/StorageObserverService(8030): DelayedDatabaseCopyHandler: Call PublishDatabase end 04-30 20:03:01.928: D/StorageObserverService(8030): Start observers 04-30 20:03:01.928: D/MediaStoreSyncObserver(8030): Start 04-30 20:03:01.938: D/TransactionManager(8030): acquireWakeLock 04-30 20:03:01.948: W/TransactionManager(8030): New ThreadSerializer id from -1 to 3594 04-30 20:03:01.948: I/TransactionManager(8030): Command: PublishDatabase 04-30 20:03:01.978: D/ExternalSQLiteOpenHelper(8030): Checkpoint result:0,4,4 04-30 20:03:01.988: D/DbUtils(8030): Creating DB copy 04-30 20:03:01.988: D/DbUtils(8030): isMainStorageAvailable? true 04-30 20:03:01.988: W/StorageUtils(8030): Delete file: /storage/emulated/0/MediaMonkey/files/mmstore.db-wal 04-30 20:03:01.988: W/StorageUtils(8030): Delete file: /storage/emulated/0/MediaMonkey/files/mmstore.db-shm 04-30 20:03:01.998: W/StorageUtils(8030): Delete file: /storage/emulated/0/MediaMonkey/files/mmstore.db-journal 04-30 20:03:01.998: W/StorageUtils(8030): Delete file: /storage/emulated/0/MediaMonkey/files/mmstore.db 04-30 20:03:01.998: D/RemoteDatabaseObserver(8030): Storage event: DELETE - mmstore.db 04-30 20:03:01.998: W/FilesMsDao(8030): Delete file from MediaStore: /storage/emulated/0/MediaMonkey/files/mmstore.db 04-30 20:03:02.078: D/StorageUtils(8030): Scan files: [/storage/emulated/0/MediaMonkey/files] 04-30 20:03:02.088: D/RemoteDatabaseObserver(8030): Storage event: CREATE - mmstore.db 04-30 20:03:02.098: D/RemoteDatabaseObserver(8030): Storage event: OPEN - mmstore.db 04-30 20:03:02.118: D/RemoteDatabaseObserver(8030): Storage event: MODIFY - mmstore.db 04-30 20:03:02.118: D/RemoteDatabaseObserver(8030): Storage event: CLOSE WRITE - mmstore.db 04-30 20:03:02.128: D/DbUtils(8030): DB copy created 04-30 20:03:02.128: D/StorageUtils(8030): Scan files: [/storage/emulated/0/MediaMonkey/files/mmstore.db] 04-30 20:03:02.418: D/StorageUtils(8030): Scanned /storage/emulated/0/MediaMonkey/files, uri=content://media/external/file/2907 04-30 20:03:02.478: D/StorageUtils(8030): Scanned /storage/emulated/0/MediaMonkey/files/mmstore.db, uri=content://media/external/file/17006 04-30 20:03:03.138: D/TransactionManager(8030): ThreadSerializer exiting 04-30 20:03:03.138: D/TransactionManager(8030): releaseWakeLock 04-30 20:03:03.138: I/TransactionManager(8030): ThreadSerializer exit 04-30 20:03:09.248: D/RemoteDatabaseObserver(8030): Storage event: 1073741856 - null 04-30 20:03:09.248: D/RemoteDatabaseObserver(8030): Storage event: 1073741840 - null 04-30 20:03:11.308: D/PlaybackService(8030): onCompletion 04-30 20:03:11.308: D/PlaybackService(8030): currentPlayerPosition:19435 04-30 20:03:11.318: D/AudioPlayer(8030): isCompletion:true 04-30 20:03:11.318: D/AudioPlayer(8030): updateTimePlayedInSession from 0 LastCurrentPosition:19435 currentPosition:19435 mStartPosition:0 04-30 20:03:11.318: D/AudioPlayer(8030): old method increment:19435 04-30 20:03:11.318: D/AudioPlayer(8030): TPS updated: 19435 04-30 20:03:11.318: D/PlaybackService(8030): updatePlaycount 04-30 20:03:11.318: D/AudioPlayer(8030): isCompletion:true 04-30 20:03:11.328: D/AudioPlayer(8030): updateTimePlayedInSession from 19435 LastCurrentPosition:19435 currentPosition:19435 mStartPosition:19435 04-30 20:03:11.328: D/AudioPlayer(8030): old method increment:0 04-30 20:03:11.358: D/dalvikvm(8030): GC_FOR_ALLOC freed 1806K, 18% free 12988K/15752K, paused 31ms, total 32ms 04-30 20:03:11.358: D/AudioPlayer(8030): TPS updated: 19435 04-30 20:03:11.368: D/MediaMonkeyStoreDbTrack(8030): calculateAndUpdatePlaycount:18 Unknown 04-30 20:03:11.368: D/MediaMonkeyStoreDbTrack(8030): Track is shorter than 3 minutes, update playcount to ...1 04-30 20:03:11.368: V/TEST(8030): updateLoggedAsync last_time_played=1398880991 playcount=1 04-30 20:03:11.368: I/Dao(8030): Atomic operation start 04-30 20:03:11.368: D/TransactionManager(8030): UI thread is putting request to TM asynchronously! 04-30 20:03:11.368: D/TransactionManager 13(8030): ThreadSerializer is turning off, starting new one... 04-30 20:03:11.368: I/Dao(8030): Atomic operation end 04-30 20:03:11.368: D/TransactionManager(8030): acquireWakeLock 04-30 20:03:11.368: D/PlaybackService(8030): TrackList is loaded. 04-30 20:03:11.368: W/TransactionManager(8030): New ThreadSerializer id from -1 to 3596 04-30 20:03:11.378: D/PlaybackService(8030): nextTrack 04-30 20:03:11.378: I/TrackList(8030): nextTrack 04-30 20:03:11.378: D/TrackList(8030): Current track position 7 tracklist size:42 04-30 20:03:11.378: I/TrackList(8030): setCurrentTrack: AudioTrack storeToPreferences:true 04-30 20:03:11.378: D/TrackList(8030): clearTrackIndexes 04-30 20:03:11.378: D/TrackListModel(8030): Store current track to preferences: De-Sci-Fer-4 Hero (Two Pages) 04-30 20:03:11.378: D/TrackListModel(8030): storeCurrentTrack pos:8 list.size:42 04-30 20:03:11.378: D/TrackListModel(8030): storeCurrentTrackInfo: InfoTrack: De-Sci-Fer-4 Hero (Two Pages) 04-30 20:03:11.378: D/TrackListModel(8030): storeCurrentTrackInfo: InfoTrack: De-Sci-Fer-4 Hero (Two Pages) 04-30 20:03:11.388: D/PlaybackService(8030): play 04-30 20:03:11.388: W/PlaybackService(8030): gainAudioFocus() 04-30 20:03:11.388: W/PlaybackService(8030): registerMediaButtonEventReceiver on checkRemoteControlClientCompact 04-30 20:03:11.388: I/PlaybackService(8030): registerMediaButtonEventReceiver 04-30 20:03:11.388: D/PlaybackService(8030): mPlayer.setNormalVolume 04-30 20:03:11.398: D/PlaybackService(8030): Track can be played AudioTrack 04-30 20:03:11.398: D/TrackList(8030): playCurrentTrack 04-30 20:03:11.418: V/TEST(8030): Updating track 04-30 20:03:11.418: D/AllMediaDao(8030): existsDirect? 04-30 20:03:11.418: D/MediaMonkeyStoreProvider 1(8030): Query: /query;Projection:null;Selection:SELECT _ID FROM media WHERE _id=?;Args:[8] 04-30 20:03:11.448: D/AudioPlayer(8030): setPlayerState to: PLAYING 04-30 20:03:11.458: D/AudioPlayer(8030): initTimePlayedInSession 04-30 20:03:11.458: D/PlaybackService(8030): enableEqualizerIfNeeded 04-30 20:03:11.458: D/EqualizerModel(8030): isEnabledEqualizer:false 04-30 20:03:11.458: D/PlaybackService(8030): updateRemoteMetadata(supported:true) - TrackInfo:De-Sci-Fer 04-30 20:03:11.458: W/PlaybackService(8030): updating RemoteControl state! 04-30 20:03:11.458: D/PlaybackService(8030): updateRemotePlaybackPosition 04-30 20:03:11.458: V/PlaybackService(8030): updateRemoteMetadata: De-Sci-Fer 04-30 20:03:11.458: D/PlaybackService 3(8030): currentTrack.getAlbumArt: file:///storage/emulated/0/Android/data/com.android.providers.media/albumthumbs/1356021195608 04-30 20:03:11.468: D/PlaybackService(8030): RemoteControlClientCompat available: true 04-30 20:03:11.468: D/PlaybackService(8030): albumArt width:320 height:294 04-30 20:03:11.478: D/PlaybackService 3(8030): currentTrack.getAlbumArt is not null true 04-30 20:03:11.498: D/dalvikvm(8030): GC_FOR_ALLOC freed 1405K, 16% free 13360K/15752K, paused 28ms, total 28ms 04-30 20:03:11.508: D/PlaybackService(8030): updateWidgets immediately 04-30 20:03:11.508: D/PlaybackService(8030): updateWidgets tracklist is loaded 04-30 20:03:11.508: D/PlayerWidgetModel(8030): Loading widget Ids 04-30 20:03:11.508: W/PlaybackService(8030): updateRemotePlaybackState isPlaying:true 04-30 20:03:11.508: I/PlaybackService(8030): refreshSuppressNotificationSounds 04-30 20:03:11.508: D/GlobalPreferences(8030): isSuppressNotificationSounds: false 04-30 20:03:11.508: D/UIUtils(8030): isAppVisible: true 04-30 20:03:11.518: D/PlaybackService(8030): updateNotification app is : in foreground isInKeyguardRestrictedInputMode: false 04-30 20:03:11.518: D/UIUtils(8030): isAppVisible: true 04-30 20:03:11.518: D/PlaybackService(8030): T2 show notification when player is playing 04-30 20:03:11.518: D/PlaybackService(8030): showNotification is Playing: true playerState: PLAYING 04-30 20:03:11.518: D/PlaybackService(8030): mUseLockScreenPlayer false 04-30 20:03:11.518: D/PlaybackService(8030): receiverRegistered false 04-30 20:03:11.518: D/PlaybackService(8030): updateWidgets tracklist is loaded 04-30 20:03:11.518: I/TrackList(8030): hasNextTrack 04-30 20:03:11.518: I/BitmapUtils(8030): albumArt:file:///storage/emulated/0/Android/data/com.android.providers.media/albumthumbs/1356021195608 04-30 20:03:11.558: D/dalvikvm(8030): GC_FOR_ALLOC freed 948K, 17% free 13083K/15752K, paused 30ms, total 31ms 04-30 20:03:11.558: D/PlaybackNotification(8030): prepareStopButton 04-30 20:03:11.568: I/BitmapUtils(8030): albumArt:file:///storage/emulated/0/Android/data/com.android.providers.media/albumthumbs/1356021195608 04-30 20:03:11.588: D/dalvikvm(8030): GC_FOR_ALLOC freed 292K, 15% free 13425K/15752K, paused 26ms, total 26ms 04-30 20:03:11.598: I/dalvikvm-heap(8030): Grow heap (frag case) to 13.501MB for 376336-byte allocation 04-30 20:03:11.628: D/dalvikvm(8030): GC_FOR_ALLOC freed <1K, 15% free 13793K/16120K, paused 31ms, total 31ms 04-30 20:03:11.628: D/PlaybackNotification(8030): prepareStopButton 04-30 20:03:11.648: D/PlaybackService(8030): updateWidgets immediately 04-30 20:03:11.648: D/PlaybackService(8030): updateWidgets tracklist is loaded 04-30 20:03:11.648: D/PlayerWidgetModel(8030): Loading widget Ids 04-30 20:03:11.648: W/PlaybackService(8030): updateRemotePlaybackState isPlaying:true 04-30 20:03:11.648: D/BroadcastSender 1(8030): SEND STATE_CHANGE_ACTION 04-30 20:03:11.658: D/BroadcastSender 1(8030): SEND NEXT_TRACK_START_ACTION is video ?false 04-30 20:03:11.658: D/PlaybackService(8030): onCompletion end 04-30 20:03:11.658: E/Provider(8030): Integrity check failed: 04-30 20:03:11.658: D/MediaStoreSyncService(8030): Service is not running 04-30 20:03:11.658: D/StorageObserverService(8030): Publish database event received. 04-30 20:03:11.658: E/MediaPlayer(8030): Should have subtitle controller already set 04-30 20:03:11.658: E/Provider(8030): rowid 2 missing from index playlist_data_idx 04-30 20:03:11.668: D/NowPlayingFragment(8030): Intent command received 04-30 20:03:11.668: D/NowPlayingFragment(8030): RECEIVE - STATE_CHANGE_ACTION 04-30 20:03:11.668: D/NowPlayingFragment(8030): REFRESH PREVIOUS TRACK INFO 04-30 20:03:11.668: E/Provider(8030): rowid 2 missing from index sqlite_autoindex_playlists_1 04-30 20:03:11.668: I/TrackList(8030): hasNextTrack 04-30 20:03:11.668: E/Provider(8030): rowid 1 missing from index media_title_type_idx 04-30 20:03:11.668: I/TrackList(8030): nextTrack 04-30 20:03:11.668: D/NowPlayingFragment(8030): updating view 04-30 20:03:11.678: E/Provider(8030): rowid 7 missing from index media_title_type_idx 04-30 20:03:11.678: E/Provider(8030): rowid 13 missing from index media_title_type_idx 04-30 20:03:11.678: E/Provider(8030): rowid 15 missing from index media_title_type_idx 04-30 20:03:11.678: D/TrialTimeUtils(8030): com.ventismedia.android.mediamonkey isProVersionInstalled: false signatureMatch:-3 04-30 20:03:11.678: E/Provider(8030): rowid 20 missing from index media_title_type_idx 04-30 20:03:11.678: E/Provider(8030): rowid 23 missing from index media_title_type_idx 04-30 20:03:11.678: D/NowPlayingActivity(8030): Activity onPrepareOptionsMenu 04-30 20:03:11.678: E/Provider(8030): rowid 3 missing from index album_name_type_idx 04-30 20:03:11.678: D/NowPlayingFragment(8030): onPrepareOptionsMenu 04-30 20:03:11.688: E/Provider(8030): rowid 4 missing from index album_name_type_idx | ||||
| Fixed in build | 283 | ||||
|
|
According to logs, integrity is corrupted during some TransactionManager operation. Sometimes it is copying of DB but not necessarily. Please check attached logs. These operations always precede before the integrity failure. TransactionManager 13 23448 ThreadSerializer is turning off, starting new one... TransactionManager 23448 acquireWakeLock TransactionManager 23448 New ThreadSerializer id from -1 to 3710 |
|
|
It seems that this is caused by something from NP view - I will continue with testing. |
|
|
Really strange. I can always replicate it on my Nexus 7, it caused by LyricsSearcher, when WebView object is created. I can reproduce it only on Nexus 7, other devices are working well. Step to reproduce: 1)show NP view (WebView object is created) 2)publish database and then check db integrity -> integrity is corrupted I'll give patch to Marek to testing and we will see, if he has same cause. |
|
|
Fixed in build 1.0.6.0283 |
|
|
Verified 303 |
