Print

Please login or register.
1 Hour 1 Day 1 Week 1 Month Forever
Login with username, password and session length

[glynor]

So... I'm really not sure what is going on, but something is fishy with newly imported files and the Auto-Sync changes with server client-side option of the Library Server.  This happened twice to me.  Note:  I was using "older" builds (the HTPC was on 132 until tonight), but I didn't see anything directly related in the change log, so I wanted to report it.

Incident One:

Over the weekend, I set up our new Eye-Fi SD card.  Fricking sweet, by the way.  Works great with MC!

Anyhow, I took two pictures with the good-old Rebel, and walked downstairs to the Server machine to check if they'd imported.  They had.  I said "awesome" and went upstairs to show my wife how it worked.

I opened MC on the HTPC (it was closed at the time).  I pulled up my Photos view and there they were at the top of the view (my Photos view sorts the newest pictures to the top).  Okay, cool.

Then, I took a few more pictures and went back to the HTPC.  I switched to a different view and waited a little while to give it a chance to sync (switching back every so often) and then I noticed something...

Not only had my new pictures not shown up, suddenly the two that were already there (the ones I'd already seen) had vanished from the view.  They just weren't there.  Anywhere in the library (not under New Imports, or in my Photos View, or whatever).  Wha?!?

I raced downstairs to check to see if the files were in MC down there, and were still on disk.  Now, note: I do NOT have MC set to remove broken links, so even if they'd been deleted, I still should have seen the "missing" record in MC on the HTPC.  But the files were still there on disk, including the new one.  They were not showing in MC on the server either, though.

I ran Auto-Import Now, and MC found them, imported them, and they popped back up in the list where they belonged.  Okay, that was odd, but there they are.  They haven't vanished again, they're still in MC now.  Subsequent tests of the Eye-Fi didn't cause it to happen again.

Incident Two:

Last night after my wife went to bed, I came back downstairs to the living room and loaded up that night's episode of The Daily Show (which had finished recording 10-15 minutes earlier).  I watched about 1/2 of the episode, pausing here and there to get a drink or listen for the baby crying (in my head) and whatnot.  MC had probably been running for at least 30 minutes at that point, if not much longer (I can't remember if it was left open when I put my wife/daughter to bed or not).

But then, literally mid-playback (not while resuming from a pause or anything), right in the middle of a segment of the episode, MC stopped playing the file and moved on to the next item in the Playing Now list.  Incidentally, this was some other show because I'd started playback from my New Shows view, which again sorts the newest files to the top (no idea if that's relevant, it just happened to be true both times).

I assumed immediately that my recording was broken and that the rest was missing.  It seemed as though it had just ended abruptly.

So I immediately stopped playback and went back to my New Video view (in Theater View this time).  The file was gone from the view.  All the other stuff was there, but that one was gone.  I switched to my regular Series view and navigated to find all the episodes of The Daily Show.  Yep, gone.

So, this time I checked from there on disk.  Yep, file sitting right there happily in the T:\recordings directory.  Now, I'm sorry, but I can't remember for sure what happened next.  I'd planned to go back downstairs again, but I never got there, and the file "re-appeared".  I might have, but I'm not sure, closed and re-opened MC on the HTPC.

In any case, that's two examples of newly imported files going all sideways and being removed from MC (once, while it was in-use) for seemingly no reason.  I got no error, and again, I don't have MC set to remove broken links, so the files shouldn't ever remove unless I delete them manually.

I'm not sure what the heck was happening, but it was disconcerting.

[glynor]

PS.  If it happens again, now that I'm looking for it, I'll be sure to keep my wits about me enough to save a log.  I didn't either time so far.

[MrHaugen]

That's a bit disturbing. I'll keep an eye open my self, even though I don't often access newly imported files right away...

[glynor]

Yeah... It is weird.

I've only seen it those two times, but the second time it happened, I knew something was off (the first time you figure it was a fluke and that you did something wrong without looking).  I mean, right during playback?

By the way, I'm guessing this has something to do with the Automatic Library Sync feature.  That's just a guess in the dark though.  But, since both times:

1. It happened when a Client copy of MC was open, while I was using it.
2. It only seemed to affect those brand-spanking-new files.
3. It seemed to happen "all at once" in a flash, and also seemed to reset the MC library back to a slightly older point in time.

It made me think that something was happening with the Client-side sync.  As though the Client was suddenly syncing "changes" back to the server, but these changes were actually a regression to an older "copy" of the library that the Client still had in a cache somewhere.

That's conjecture though.  All I know is what happened.  Both times it was on a client copy of MC.  Both times I happened to be looking at or using a View sorted with the newest files on top.  Both times the only files impacted were those that had been very recently imported.  Once I was flipping around in between different views, but nothing was "playing".  One time the file that got removed, was actively playing at the time (and when this happened, playback ended).

[InflatableMouse]

Don't mind me asking, but how is your client-server setup?

I can try and replicate it if I know how you've set it up.

[eapool]

I had a similar issue happen on Tuesday night.  I was reluctnant to post because it was so strange I figured it was operator error.  I was running 17.0.132 on the client and the server and I record in .ts format.

I started watching a recorded show on a client machine, about 8:30 PM.  While selecting the show, I verified that the three scheduled recordings were being recorded (2 OTA and 1 DTV via Colossis).  I did this by verifying that there were showing up in theater view.  When I finished watching the recorded show, I decided to watch one of the shows that had just finished recording and it wasn't there.  I thought this was pretty stange since I knew it was being recorded.  I then checked and all three of the recorded shows were not showing in theater view.  I switched to standard view and they were not showing up either.  I then selected 'tv' and selected recordings and they weren't even showing in the list of recordings.  I found this strange because I was sure I had seen them in theater view earlier.  At this point, I figured I was just wrong.  I decided to check the T:\Recordings directory to be sure.  Sure enough all three recordings were there.  They did not have a JRSidecar file though.  I then ran an import on that directory and they did not import (I had the ignore previous files checked).  When I unchecked the ignore previous files and reran the import it found all the missing shows.  I decided to update to 17.0.133 (on the server), just incase there was a fix.  I was currently recording additional shows, so, thos recordings were stopped and restarted when MC restarted.  The exact same thing happened, they appeared in MC until they were complete at the point the recording ended, they were removed from MC, but the file remained and I could import it.

I verified that the recordings earlier in the day were fine, the last one was a recording from 4-4:30 and everything recorded on Wednesday was fine.  I have no idea what happened and as Glynor said, I didn't keep the logs, because I figured it was something I did.  I was not going to post at all until I saw Glynor's post.  I believe there was a windows update to one of the boxes on Tuesday, but I can't remember which one.  Either way, they are not automatically installed, and I did not install it during this issue.

Alex

[eapool]

I had this issue occur again last night.  I record three shows that start at 9 PM, The Office, Person Of Interest, and Touch.  All three were recorded, but are not showing in Media Center.  The files are on my hard drive.  Two shows (The Office and Person Of Interest) have Sidecar files, Touch does not.  I have captured a log and I was able to see where Person of Interest was removed from MC, but I am not sure why.  Also, it appears that all the shows recorded before and after these 9 oclock shows are fine.

Let me know, if you would like the log.

Alex

[glynor]

I haven't seen it again yet, but I was sleeping yesterday evening, and didn't do much with MC.  Unlike most days when I just don't sleep, I had to yesterday...  Hit some physical overclocking limits.  

[Matt]

Next build:
Fixed: Library Server sync could cause problems in certain cases (only applies to the last few builds).
Faster: Improved the performance of Library Server sync.

It's complicated to explain, but basically the client could lose the connection to the server file when doing a reverse-merge due to how the database dirty state was being tracked. 

It started when we switched from filenames to library keys to build deltas (a few builds ago).

Sorry for the trouble.

[glynor]

Thanks, Matt!

[glynor]

This happened again to me twice tonight on build 151 (both client and server).  I'm pretty sure it was happening with new imports yesterday too, but I'm not sure as I was just getting everything up and running again.

Watched it happen tonight, though, twice with the same file.

I have the log from the server and I'll post it later tonight (too big for the attachment because it has been running since yesterday).

[glynor]

http://glynor.com/files/jriver/AutoImport_Removal-Log.zip

[glynor]

Any ideas?  See what happened in the log, there?

[glynor]

Here's where MC found the file that I watched it happen with.  I was paying attention because I had to download this one (it aired while my system was down).  I watched it import on the server downstairs (and was confused that it wasn't already there), and then when I tried to play it, it had vanished on the HTPC and the server.

Then, I re-imported it, and watched it happen again on the server itself.

Code: [Select]

69966839: 1744: Import: ImportNewFiles: Start
69966839: 1744: Import: ImportNewFiles: Adding: M:\Incoming\Game.of.Thrones.S02E06.720p.HDTV.x264-2HD.mkv
69966839: 1744: Database: CMediaDatabase::AddFile: JRAnalyzer: 0x5d7d638
69966839: 1744: Database: CMediaDatabase::AddFile: Calling JRAnalyzer::Open
69966839: 1744: Import: JRAnalyzer::Open: Start
69966839: 1744: Import: JRAnalyzer::AddFile: Start
69966839: 1744: Import: JRAnalyzer::AddFile: Filename: M:\Incoming\Game.of.Thrones.S02E06.720p.HDTV.x264-2HD.mkv
69966839: 1744: Import: JRAnalyzer::AddFileJRWorkerExe: Start
69966839: 1744: Import: JRAnalyzer::AddFileJRWorkerExe: Parameters: /AnalyzeDX "M:\Incoming\Game.of.Thrones.S02E06.720p.HDTV.x264-2HD.mkv" "C:\Users\glynor\AppData\Roaming\J River\Media Center 17\Temp\Analyze - 1744.xml"
69966839: 1744: General: RunProgram: Start
69966839: 1744: General: RunProgram: Filename: C:\Program Files (x86)\J River\Media Center 17\JRWorker.exe / Parameters: /AnalyzeDX "M:\Incoming\Game.of.Thrones.S02E06.720p.HDTV.x264-2HD.mkv" "C:\Users\glynor\AppData\Roaming\J River\Media Center 17\Temp\Analyze - 1744.xml"
69966839: 1744: General: RunProgram: Performing ShellExecute...
69966839: 1744: General: RunProgram: Running process...
69966839: 1744: General: RunProgram: Waiting for completion
0000031: 8784: General: JRWorker::ProcessCommand: Start
0000031: 8784: General: JRWorker::ProcessCommand: Processing AnalyzeDX task...
0000031: 8784: Import: CJRVideoAnalyzeHelper::AnalyzeFileDX: Start
0000031: 8784: Import: CJRVideoAnalyzeHelper::AnalyzeFileDX: Filename: M:\Incoming\Game.of.Thrones.S02E06.720p.HDTV.x264-2HD.mkv, File Type: mkv
0000062: 8784: Playback: DShowVideoGraph::Render: Start
0000062: 8784: Playback: DShowVideoGraph::ConnectSourceAndSplitter: Start
0000078: 8784: Playback: DShowVideoGraph::ConnectSourceAndSplitter: Finish (16 ms)
0000078: 8784: Playback: CStreamSelectionList::FindStreams: Start
0000078: 8784: Playback: CStreamSelectionList::UpdateStreamsList: Start
0000078: 8784: Playback: CStreamSelectionList::UpdateStreamsList: Number of streams: 2
0000078: 8784: Playback: CStreamSelectionList::UpdateStreamsList: Stream 0, Name V: English [eng] (h264 high L4.1, yuv420p, 1280x720) [default], Group 0, flag 3, lcid 0x409, hr = 0x0
0000078: 8784: Playback: CStreamSelectionList::UpdateStreamsList: Stream 1, Name A: ac3, 48000 Hz, stereo, 384 kb/s [default], Group 1, flag 3, lcid 0x0, hr = 0x0
0000078: 8784: Playback: CStreamSelectionList::UpdateStreamsList: Finish (0 ms)
0000078: 8784: Playback: CStreamSelectionList::FindStreams: Finish (0 ms)
0000078: 8784: Playback: CDShowFilterGraph::SetupVideoWindow: Start
0000078: 8784: Playback: CDShowFilterGraph::SetupVideoWindow: Finish (0 ms)
0000078: 8784: Playback: DShowVideoGraph::Render: Rendering success: 1
0000078: 8784: Playback: DShowVideoGraph::Render: Finish (16 ms)
0000078: 8784: Import: CJRVideoAnalyzeHelper::AnalyzeFileDX: Got duration
0000078: 8784: Import: CJRVideoAnalyzeHelper::AnalyzeFileDX: Found video renderer
0000078: 8784: Import: CJRVideoAnalyzeHelper::AnalyzeFileDX: getting bitrate
0000078: 8784: Import: CJRVideoAnalyzeHelper::AnalyzeFileDX: Getting other tag data for local file
0000078: 8784: Import: CJRVideoAnalyzeHelper::AnalyzeFileDX: Finish (47 ms)
0000078: 8784: General: JRWorker::ProcessCommand: AnalyzeDX succeeded...
0000078: 8784: General: JRWorker::ProcessCommand: Task completed in 59 ms, result = 0
0000078: 8784: General: JRWorker::ProcessCommand: Finish (47 ms)
69966995: 1744: General: RunProgram: Finished
Then, further down after thumbnailing is done and all of that, I see this:

Code: [Select]

69983094: 9928: Database: CDataHolder::Save: Field: Actors; Elapsed ms: 59.824
69983094: 9928: Database: CMediaFileIOSave::Load: Saving: M:\library_data\andoria\field (critic rating).jmd
69983141: 9928: Database: CDataHolder::Save: Field: Critic Rating; Elapsed ms: 41.672
69983141: 9928: Database: CMediaFileIOSave::Load: Saving: M:\library_data\andoria\playlistx.jmd
69983266: 9928: Database: MCDB::Save: Finish (1607 ms)
69983266: 9928: Database: CTagSaveHelper::CTagSaveHelper: Start
69983266: 9928: Database: CTagSaveHelper::CTagSaveHelper: Finish (0 ms)
69983266: 9928: Database: CTagSaveHelper::SubmitFile: Start
69983266: 9928: Database: CTagSaveHelper::SubmitFile: Submitting: M:\Incoming\Game.of.Thrones.S02E06.720p.HDTV.x264-2HD.mkv
69983266: 9928: Database: CDataHolder::Load: Field: Stack Tag; Files: 72612; Pointer bytes: 9608; Data bytes: 4168; Elapsed ms: 0.280
69983281: 9928: Database: CDataHolder::Load: Field: Comment; Files: 72612; Pointer bytes: 290596; Data bytes: 374792; Elapsed ms: 1.721
<etc>
And then this:

Code: [Select]

69983328: 9928: Database: CTagSaveHelper::SubmitFile: Finish (62 ms)
69983328: 9928: Database: MCDB::Unload: Start
69983328: 9928: Database: MCDB::Unload: Stopping worker threads
69983328: 9928: Database: MCDB::Unload: Getting database lock
69983328: 9928: Database: MCDB::Unload: Starting unload
69983328: 9928: Database: MCDB::Unload: Stopping playback
69983328: 9928: Database: MCDB::Unload: Waiting for tagging to finish
69983328: 11224: Database: CTagSaveHelper::Thread: Start
69983328: 9928: Database: MCDB::Unload: Saving database
69983328: 9928: Database: MCDB::Unload: Updating child objects after unload
69983328: 9928: Database: MCDB::Unload: Resetting info
69983328: 11224: Database: CTagSaveHelper::Thread: Saving tag: M:\Incoming\Game.of.Thrones.S02E06.720p.HDTV.x264-2HD.mkv
69983328: 11224: Import: JRAnalyzer::Open: Start
69983328: 11224: Import: JRAnalyzer::AddFile: Start
69983328: 11224: Import: JRAnalyzer::AddFile: Filename: M:\Incoming\Game.of.Thrones.S02E06.720p.HDTV.x264-2HD.mkv
69983328: 11224: Import: JRAnalyzer::AddFile: Start
69983328: 11224: Import: JRAnalyzer::AddFile: Filename: M:\Incoming\Game.of.Thrones.S02E06.720p.HDTV.x264-2HD.mkv
69983328: 11224: Import: JRAnalyzer::AddFileJRWorkerExe: Start
69983328: 9928: Database: MCDB::Unload: Finish (0 ms)
69983328: 9928: Sharing Plugins: JRWebService::Process: Finish (1685 ms)
69983328: 9928: Sharing Plugins: VHTTPMessage::Write: Wrote 417 bytes
69983328: 9928: Sharing Plugins: CHTTPRequestMessage::ReadPreamble: Failed to read rest of first line
69983328: 9928: Sharing Plugins: CHTTPListenerWorker::HandleRequest: Failed to read request
69983328: 9928: Sharing Plugins: VHTTPMessage::Write: Wrote 138 bytes
69983328: 9928: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Finish (1701 ms)
69983328: 11224: Import: JRAnalyzer::AddFileJRWorkerExe: Parameters: /AnalyzeDX "M:\Incoming\Game.of.Thrones.S02E06.720p.HDTV.x264-2HD.mkv" "C:\Users\glynor\AppData\Roaming\J River\Media Center 17\Temp\Analyze - 11224.xml"
69983328: 11224: General: RunProgram: Start
Which near the end, looks like the Library Sharing system is throwing some "failed to read" errors, after which (or at the same time, maybe), MC seems to start importing the file again from scratch.  That was the first example in the log file, but you should be able to see the same thing happen again further down.

[Matt]

glynor, I'll put on my thinking cap and take a close look at the logs tomorrow.

But just to make sure I understand, will you state what "this happened again" means as simply as possible.  I think you're saying clients are showing files then losing them.  Is that correct?  Does the client auto-import, or only the server?

[glynor]

Thanks.

To answer your questions...

But just to make sure I understand, will you state what "this happened again" means as simply as possible.  I think you're saying clients are showing files then losing them.  Is that correct?

Both the client and the server are losing the files.  The process:

1. Server and Client are both open.
2. Server sees and imports a new file.
3. Time passes (but not much).
4. New file vanishes from the database.  If the view is still visible, it actually leaves a blank line where the file used to be listed in the Details View.

EDIT: The file then does not re-auto-import on it's own, until I run the scan manually (I don't have the "Ignore Files previously removed" option enabled anywhere).  Perhaps it would re-import eventually if some other filesystem change triggered the scan, but even leaving it for a long time doesn't seem to trigger the re-import on its own.

Does the client auto-import, or only the server?

You know... It shouldn't have been.  But, since you asked, I checked.  In this instance (until just now), Auto-Import was, accidentally, enabled on the Client too.

Typically, I have auto-import disabled on the Client copies.  But... When my server was down, I was running everything off of the HTPC (it was directly accessing the library, from one of my backup drives), and I turned it on.  Now that I switched back and reconnected the HTPC back to the now-running-again server, I forgot to turn that back off.  It was still enabled.  And it was watching all the same locations as the server would have been (the Auto-Import dialogs looked identical at a cursory glance).

So... Would this cause it?

[glynor]

If so, it would happen all the time with my Laptop.  It uses its own Library much of the time, and I want to run Auto-Import there when that Library is open.  But I also connect with my Laptop to a few different servers (home and work ones).  I don't need to run Auto-Import from the client when I'm on those, since the server will handle it.  I don't connect to my home Library with my laptop every day...  Sometimes not for weeks at a time (I go in fits and starts).  I do, however, use the work server almost every day now.

But I've basically always had Auto-Import "globally enabled" this way on my Laptop, and never encountered similar problems with Auto-Import before, even with MC16 and before.

Plus... The UI is all funky around this stuff now.  When I'm connected on a Client, I see that Tools -> Import is grayed out and unavailable.  PS. It's annoying that I can't do a manual import when I need to (which seemed to work before without trouble).  Either way, because it is grayed out there, I think a reasonable user would assume the whole system is disabled while connected to a remote Library Server.

However, under Tools -> Options -> Library & Folders, there it is, the checkbox and Auto-Import dialog available.  I figured it didn't "do anything", honestly, since the Tools -> Import widget was disabled.  But, in this case it was enabled "left over" from when I was using a different Library.  I think I've usually had the global option unchecked on the HTPC (since it basically never does anything but connect to the server), until this.  On the Laptop, though, it is probably turned on now and has always been.

[Matt]

The full log you posted is for the server.

It shows that a client is sending requests to remove files like:
0876741: 2248: Sharing Plugins: CHTTPListenerWorker::HandleRequest: TCP: 192.168.0.10: POST: http://daecion.andoria.lan:10630/MCWS/v1/Library/Merge
0876773: 2248: Database: CMediaDatabase::RemoveFileAbsolute: Filename: T:\recordings\TheKilling-S02E08-OfftheReservation-9580747-0.ts Mode: 0  Track: 0

Then later auto-import brings the file back:
0996581: 7692: Import: ImportNewFiles: Adding: T:\recordings\TheKilling-S02E08-OfftheReservation-9580747-0.ts

It seems wrong that the client requested the file to be removed.  It should only remove files that it got from the server but have since been removed from the client (which should only happen manually, unless auto-import on the client is the problem).

Any chance you have the log from the client?  If not, any chance you could grab it next time?

Thanks.

[glynor]

Any chance you have the log from the client?  If not, any chance you could grab it next time?

Thanks.

No, but yes.

And in those cases, they certainly were not removed manually.

[MrHaugen]

Have you found more problems here Glynor?