search

jansmolders86 / mediacenterjs

A HTML/CSS/Javascript (NodeJS) based Media center
http://mediacenterjs.com
1.29k stars 245 forks source link

lot of `EMFILE` errors #100

Closed vprimachenko closed 10 years ago

vprimachenko commented 10 years ago

from the log

Metadata fetcher error:  { [Error: Command failed:
events.js:72
        throw er; // Unhandled 'error' event
              ^
Error: EMFILE, open 'D:\Music\redacted.mp3'
] killed: false, code: 8, signal: null }
awafaa-zz commented 10 years ago

I am getting the same when trying to access any music. Nothing is displayed so I can't actually use this functionality.

jansmolders86 commented 10 years ago

Thanks guys for letting me know of this issue. How many files are you trying to index if I may ask? I have not thoroughly tested the music functionality with large collections, so this could be a great test case! :)

In any case I will definitely have a look to find a solution.

Thanks again!

awafaa-zz commented 10 years ago

Hi Jan,

My music library is roughly 13717 tracks in roughly 920 directories (893 albums).

vprimachenko commented 10 years ago

approx 17k files

jansmolders86 commented 10 years ago

Wow that's a lot guys! the amount of files exceeds the default threshold of 10240 files which is why the error occurs. I'll implement a additional node module called "gracefull-fs" to handle files exceeding this limit.

I'll let you know when I'm done implementing this. If you guys would be so kind to test the fix once it is done, that would be really awesome!

vprimachenko commented 10 years ago

sure, i also made some ugly-hack fix (put the closure from music-metadata.js in a setTimeout with increassinv interval i+=100) now when i visit /music console says

MediacenterJS listening on port:80

Screen ready...
Getting album data
Looking for stored albums.
Screen ready...
Found albums...
Found 209 albums, getting additional data...
Getting album data
Looking for stored albums.
Found albums...
Found 209 albums, getting additional data...
Getting album data
Looking for stored albums.
Screen ready...
Found albums...
Found 209 albums, getting additional data...

i do not refresh the page, (and the start page doesnt show the thumbs anymore, i have to make them visible via inspector) how can i help diagnose the issues better?

jansmolders86 commented 10 years ago

Cool you made quick fix! I would love to know what the loading times are before and after the index of the music library.

This is a tricky thing to solve. Does the console continue to search for albums and does the screen say "loading"? Or is it blank?

vprimachenko commented 10 years ago

screen says "LOADING, PLEASE WAIT..." the console just repeats those 4 lines over and over

jansmolders86 commented 10 years ago

I have a feeling I might know what the problem is. Due to asynchronous nature of the database functions and the settimeout used to overcome the too many files issue, the actually getting of additional data (function in music-functions for getting the appropriate tracks) is not done correctly. I will have to think about a solution as this is a bit tricky :) hope you dont mind !

vprimachenko commented 10 years ago

take your time, its an alpha, so its cool (btw how would i reset the databases to try a clean rescan)

jansmolders86 commented 10 years ago

Thanks for understanding. You can reset a certain database (eg music or movies) in the settings (/settings)

jansmolders86 commented 10 years ago

Hej There,

I have added graceful-fs as a potential remedy . I've pushed this "fix" in a separate branch. Would you be so kind and check if the scraper handles the amount of files you have now?

To clone the separate branch use this commandline:

 git clone https://github.com/jansmolders86/mediacenterjs.git -b music-fix
awafaa-zz commented 10 years ago

Hi,

Just tried the new branch and I get a more descriptive error which I never got before:

Screen ready...
Current version up to date.
Getting album data
Looking for stored albums.
Screen ready...
Database error: Error: Error: near line 1: no such table: albums

No albums found... Indexing.
Fetching metadata
Meta gathering started: music

13717 files found.

fs.js:427

  return binding.open(pathModule._makeLong(path), stringToFlags(flags), mode);
                 ^

Error: EMFILE, too many open files '/home/andrew/Code/musicfix/node_modules/musicmetadata/lib/id3v2.js'
    at Object.fs.openSync (fs.js:427:18)
    at Object.fs.readFileSync (fs.js:284:15)
    at Object.Module._extensions..js (module.js:473:44)
    at Module.load (module.js:356:32)
    at Function.Module._load (module.js:312:12)
    at Module.require (module.js:364:17)
    at require (module.js:380:17)
    at ReadStream.<anonymous> (/home/andrew/Code/musicfix/node_modules/musicmetadata/lib/index.js:32:5)
    at ReadStream.g (events.js:175:14)
    at ReadStream.EventEmitter.emit (events.js:95:17)

Metadata fetching for music complete...
Looking for stored albums.
Child process exited for:  music
Metadata fetcher error:  { [Error: Command failed: 
fs.js:427
  return binding.open(pathModule._makeLong(path), stringToFlags(flags), mode);
                 ^
Error: EMFILE, too many open files '/home/andrew/Code/musicfix/node_modules/musicmetadata/lib/id3v2.js'
    at Object.fs.openSync (fs.js:427:18)
    at Object.fs.readFileSync (fs.js:284:15)
    at Object.Module._extensions..js (module.js:473:44)
    at Module.load (module.js:356:32)
    at Function.Module._load (module.js:312:12)
    at Module.require (module.js:364:17)
    at require (module.js:380:17)
    at ReadStream.<anonymous> (/home/andrew/Code/musicfix/node_modules/musicmetadata/lib/index.js:32:5)
    at ReadStream.g (events.js:175:14)
    at ReadStream.EventEmitter.emit (events.js:95:17)
] killed: false, code: 8, signal: null }
jansmolders86 commented 10 years ago

Hej Andrew,

Thanks for the log. I think I may have solved the issue. I found a really stupid mistake in the metadata fetcher. I did not close the fs.createreadwrite handling, so the files accumulated in the memory buffer during the scraping.

I pushed the fix for this in the music branch. This is something that needed to be done anyway, but hopefully this will solve the problems you are having.

Thank you for testing. You're help is really appreciated!

awafaa-zz commented 10 years ago

Hey Jan,

No problem. Unfortunately things don't seem to be working still. I did both a git pull and a fresh checkout of the music branch and both error:

Screen ready...
Current version up to date.
Getting album data
Looking for stored albums.
Screen ready...
Database error: Error: Error: near line 1: no such table: albums

No albums found... Indexing.
Fetching metadata
Meta gathering started: music

13717 files found.

fs.js:427

  return binding.open(pathModule._makeLong(path), stringToFlags(flags), mode);

        ^

Error: EMFILE, too many open files '/home/andrew/Code/musicfix/node_modules/musicmetadata/lib/id3v2.js'
    at Object.fs.openSync (fs.js:427:18)
    at Object.fs.readFileSync (fs.js:284:15)
    at Object.Module._extensions..js (module.js:473:44)
    at Module.load (module.js:356:32)
    at Function.Module._load (module.js:312:12)
    at Module.require (module.js:364:17)
    at require (module.js:380:17)
    at ReadStream.<anonymous> (/home/andrew/Code/musicfix/node_modules/musicmetadata/lib/index.js:32:5)
    at ReadStream.g (events.js:175:14)
    at ReadStream.EventEmitter.emit (events.js:95:17)

Metadata fetching for music complete...
Looking for stored albums.
Child process exited for:  music
Metadata fetcher error:  { [Error: Command failed: 
fs.js:427
  return binding.open(pathModule._makeLong(path), stringToFlags(flags), mode);
                 ^
Error: EMFILE, too many open files '/home/andrew/Code/musicfix/node_modules/musicmetadata/lib/id3v2.js'
    at Object.fs.openSync (fs.js:427:18)
    at Object.fs.readFileSync (fs.js:284:15)
    at Object.Module._extensions..js (module.js:473:44)
    at Module.load (module.js:356:32)
    at Function.Module._load (module.js:312:12)
    at Module.require (module.js:364:17)
    at require (module.js:380:17)
    at ReadStream.<anonymous> (/home/andrew/Code/musicfix/node_modules/musicmetadata/lib/index.js:32:5)
    at ReadStream.g (events.js:175:14)
    at ReadStream.EventEmitter.emit (events.js:95:17)
] killed: false, code: 8, signal: null }
awafaa-zz commented 10 years ago

I just tried using the music branch with a directory of only 68 tracks/5 albums (6 directories) and it errored out. The log is:

Screen ready...
Getting album data
Looking for stored albums.
Screen ready...
Database error: Error: Error: near line 1: no such table: albums

No albums found... Indexing.
Fetching metadata
Meta gathering started: music

68 files found.

Employment (Bonus Disc)

Employment (Bonus Disc)

Employment (Bonus Disc)

Employment (Bonus Disc)

Employment (Bonus Disc)

Employment (Bonus Disc)

Employment

Employment

Employment

Employment

Employment

Employment

Employment

Employment

Employment

Employment

Employment

Employment

The Future Is Medieval

The Future Is Medieval

The Future Is Medieval

The Future Is Medieval

The Future Is Medieval

The Future Is Medieval

The Future Is Medieval

The Future Is Medieval

The Future Is Medieval

The Future Is Medieval

The Future Is Medieval

The Future Is Medieval

The Future Is Medieval
The Future Is Medieval

The Future Is Medieval

The Future Is Medieval

The Future Is Medieval

The Future Is Medieval

The Future Is Medieval

The Future Is Medieval

Lap Of Honour

Lap Of Honour

Lap Of Honour

Lap Of Honour

Lap Of Honour

Lap Of Honour

Lap Of Honour

Education, Education, Education & War

Education, Education, Education & War

Education, Education, Education & War

Education, Education, Education & War

Education, Education, Education & War

Education, Education, Education & War

Education, Education, Education & War

Education, Education, Education & War

Education, Education, Education & War

Education, Education, Education & War

Start The Revolution Without Me

Start The Revolution Without Me

Start The Revolution Without Me
Start The Revolution Without Me
Start The Revolution Without Me
Start The Revolution Without Me
Start The Revolution Without Me

Start The Revolution Without Me

Start The Revolution Without Me

Start The Revolution Without Me
Start The Revolution Without Me
Start The Revolution Without Me

Start The Revolution Without Me

(node) warning: possible EventEmitter memory leak detected. 11 listeners added. Use emitter.setMaxListeners() to increase limit.

Trace
    at Socket.EventEmitter.addListener (events.js:160:15)
    at Socket.Readable.on (_stream_readable.js:689:33)
    at Socket.EventEmitter.once (events.js:179:8)
    at Request.onResponse (/home/andrew/Code/musicfix/node_modules/request/index.js:623:25)
    at ClientRequest.g (events.js:175:14)
    at ClientRequest.EventEmitter.emit (events.js:95:17)
    at HTTPParser.parserOnIncomingClient [as onIncoming] (http.js:1689:21)
    at HTTPParser.parserOnHeadersComplete [as onHeadersComplete] (http.js:120:23)
    at Socket.socketOnData [as ondata] (http.js:1584:20)
    at TCP.onread (net.js:525:27)

(node) warning: possible EventEmitter memory leak detected. 11 listeners added. Use emitter.setMaxListeners() to increase limit.

Trace
    at Socket.EventEmitter.addListener (events.js:160:15)
    at Socket.Readable.on (_stream_readable.js:689:33)
    at Socket.EventEmitter.once (events.js:179:8)
    at Request.onResponse (/home/andrew/Code/musicfix/node_modules/request/index.js:623:25)
    at ClientRequest.g (events.js:175:14)
    at ClientRequest.EventEmitter.emit (events.js:95:17)
    at HTTPParser.parserOnIncomingClient [as onIncoming] (http.js:1689:21)
    at HTTPParser.parserOnHeadersComplete [as onHeadersComplete] (http.js:120:23)
    at Socket.socketOnData [as ondata] (http.js:1584:20)
    at TCP.onread (net.js:525:27)

(node) warning: possible EventEmitter memory leak detected. 11 listeners added. Use emitter.setMaxListeners() to increase limit.

Trace
    at Socket.EventEmitter.addListener (events.js:160:15)
    at Socket.Readable.on (_stream_readable.js:689:33)
    at Socket.EventEmitter.once (events.js:179:8)
    at Request.onResponse (/home/andrew/Code/musicfix/node_modules/request/index.js:623:25)
    at ClientRequest.g (events.js:175:14)
    at ClientRequest.EventEmitter.emit (events.js:95:17)
    at HTTPParser.parserOnIncomingClient [as onIncoming] (http.js:1689:21)
    at HTTPParser.parserOnHeadersComplete [as onHeadersComplete] (http.js:120:23)
    at Socket.socketOnData [as ondata] (http.js:1584:20)
    at TCP.onread (net.js:525:27)

(node) warning: possible EventEmitter memory leak detected. 11 listeners added. Use emitter.setMaxListeners() to increase limit.

Trace
    at Socket.EventEmitter.addListener (events.js:160:15)
    at Socket.Readable.on (_stream_readable.js:689:33)
    at Socket.EventEmitter.once (events.js:179:8)
    at Request.onResponse (/home/andrew/Code/musicfix/node_modules/request/index.js:623:25)
    at ClientRequest.g (events.js:175:14)
    at ClientRequest.EventEmitter.emit (events.js:95:17)
    at HTTPParser.parserOnIncomingClient [as onIncoming] (http.js:1689:21)
    at HTTPParser.parserOnHeadersComplete [as onHeadersComplete] (http.js:120:23)
    at Socket.socketOnData [as ondata] (http.js:1584:20)
    at TCP.onread (net.js:525:27)

(node) warning: possible EventEmitter memory leak detected. 11 listeners added. Use emitter.setMaxListeners() to increase limit.

Trace
    at Socket.EventEmitter.addListener (events.js:160:15)
    at Socket.Readable.on (_stream_readable.js:689:33)
    at Socket.EventEmitter.once (events.js:179:8)
    at Request.onResponse (/home/andrew/Code/musicfix/node_modules/request/index.js:623:25)
    at ClientRequest.g (events.js:175:14)
    at ClientRequest.EventEmitter.emit (events.js:95:17)
    at HTTPParser.parserOnIncomingClient [as onIncoming] (http.js:1689:21)
    at HTTPParser.parserOnHeadersComplete [as onHeadersComplete] (http.js:120:23)
    at Socket.socketOnData [as ondata] (http.js:1584:20)
    at TCP.onread (net.js:525:27)

Metadata fetching for music complete...
Looking for stored albums.
Child process exited for:  music
jansmolders86 commented 10 years ago

Thanks for understanding Andrew! It's difficult fixing this "blind", although I feel we are getting closer to the solution. I will refactor a portion of the code to handle more then 10000 files.

With that in mind, your 6 albums should not present any problems. I also do not see any errors in the log, just warnings. If you refresh the music page, do you see your albums?

awafaa-zz commented 10 years ago

Hi Jan,

Yes, you are quite correct (naturally), refreshing does indeed result in displaying and enabling access to the albums (for the 6 albums).

jansmolders86 commented 10 years ago

Hej Andrew,

Good news, I finished my refactoring. The scraper should be a lot more stable and a lot faster. There is also better status logging in the console and hopefully, no EMFILE errors!

Would you be so kind and test this in the music-fix branch. Once you give the ok, I can merge this in develop!

Thanks again!

vprimachenko commented 10 years ago

so yeah… i tested the new update and found in interesting issue: when scanning for metadata there are sometimes 3 instances of node music-metadata.js running. once the prograss reaches 99% the first instance quits yet nothing in displayed in web-interface, the latter two instances are still running. i let them run for few minutes, eventullay killed them via task manager and then data was send to client. i tested this on a single artist folder (21 reported albums, ~400 tracks) and the result is satisfactory, i have albums, art and can listen to music. (while scanning tho the counr in the console started from Item 4 from 394, 1% done and not from 1)

when trying to scan my entire library i got a lot of database locked errors approx after 500 scanned tracks (which took ~10minutes to scan, while said single artist folder was done in ~30 seconds)

vprimachenko commented 10 years ago

also i have 6 (!) instaces of ./bin/sqlite3/sqlite3 -csv C:\MediacenterJS\lib\database\mcjs.sqlite running, which i suspect an error too

vprimachenko commented 10 years ago

exceprt from the console

Item 540 from 836, 64% done
Item 541 from 836, 64% done
Item 542 from 836, 64% done
Item 543 from 836, 64% done
Getting album data
Looking for stored albums.
Found albums...
Found 76 albums, getting additional data...
Item 544 from 836, 65% done
Item 545 from 836, 65% done
Item 546 from 836, 65% done
Item 547 from 836, 65% done
Item 548 from 836, 65% done
Item 549 from 836, 65% done

and the process tree

mediacenter

jansmolders86 commented 10 years ago

My god! This rabbithole is just getting deeper and deeper. I'm so sorry this is taking me some time to fix. So the emfile errors are gone, but too many processes are started? I think I understand the sql processes. But the many node processes are very strange. What happens if you call the scraper directly? Eg in the root of mcjs, typ "node lib/utils/metadata/music-metadata.js" does this improve performance and process consumption?

vprimachenko commented 10 years ago 
C:\MediacenterJS>node lib/utils/metadata/music-metadata.js
Starting scan for 836 files
Item 9 from 836, 1% done
Item 10 from 836, 1% done
err  { error: 6, message: 'Album not found', links: [] }
Item 11 from 836, 1% done
…
err  { error: 6, message: 'Artist not found', links: [] }
Item 834 from 836, 99% done
err  { error: 6, message: 'Artist not found', links: [] }

and then it just stays so and i have to close it manually. The EMFILE errors are inded gone

Opening the web interface then gets stuck at

info: socket.io started
MediacenterJS listening on port:3000

Getting album data
Looking for stored albums.
Screen ready...
Found albums...
Found 80 albums, getting additional data...
jansmolders86 commented 10 years ago

Cool vprimachenko Thanks for trying! Couple of questions:

1) When scraping directly how many processes are started? 2) How long does 800 items take to scrape? 3 ) Do you have both an album and tracks table in the database?

jansmolders86 commented 10 years ago

vprimachenko! I think I know why you had so many processes running!

I have added a function that allows the scraping to be scheduled. Now though, It is set fixed to an interval of 30 minutes. So every 30th minute of the hour, all scrapers (eg movies, music and tv) are run asynchronously.

That would explain the multiple processes! I still have to make the scheduled task "smart" to take in account already running tasks and video playback.

I will merge this scraper to master as it fixes the problems you where having. I also made the logging a bit better with time elapsed at the end of the scraping and properly closing database connections if needed.

Then I will swiftly work on getting the scheduler more robust.

vprimachenko commented 10 years ago

very cool! 1) When scraping directly how many processes are started? only one 2) How long does 800 items take to scrape? approx 20 minutes while locking any programs which read/wrote to that drive, but well, those 800 files are approx 8gig 3) Do you have both an album and tracks table in the database? i have reset the storage per settings menu and run the scrapper then

jansmolders86 commented 10 years ago

Cool! 20 minutes is still a long time but i think I got most out of what nodejs can give. I added a check to the scheduled task so it will not start if the database is in use. I merged everything in master. Only thing left to do is kill trailing spawns of sqlite from the main app. But that is a different issue all together.

vprimachenko commented 10 years ago

what about the entire thing getting stuck at Found 80 albums, getting additional data...

jansmolders86 commented 10 years ago

I suggest I'll tackle that issue together with issue #103 and close this issue as it is getting failry large and the issue description is no longer fitting. Agreed?

vprimachenko commented 10 years ago

sure