lazy or nonworking media-monitor
  • Hi!

    Something is wrong with media-monitor on my install. It's lazy or nonworking. After I add a folder as a media watched folder I get in the log a rich output, which concludes with 
    2013-02-20 01:27:20,095 INFO - [Thread-5] [bootstrap.py : flush_watch()] : LINE 63 - Flushed watch directory (/store).                 (added, modified, deleted) = (1350, 0, 0)
    and then nothing happens. It get's into a state and it at 3 sec it writes this line to the log
    2013-02-20 01:27:27,542 INFO - [Thread-3] [watchersyncer.py : run()] : LINE 34 - We have 3 requests waiting to be launched
    I noticed that over the night it added to the library some of my files, but not all of them.
    And now, after I did some add/remove operations of the watch folder...no more files get added but it's even worse. I don't get that line counting the files added,removed, deleted. Instead, it's stuck on some files I deleted.

    Attached you find a media-monitor log from which I cut some repeating output listing all my music folders.

    What's wrong?

    Alexandru

  • 22 Comments sorted by
  • Now even uploading a file through the web ui doesn't trigger media-monitor anymore so it's not listed in the library. airtime-check report no problems.

    Alexandru
  • Vote Up0Vote Down Cliff WangCliff Wang
    Posts: 339Member, Sourcefabric Team
    Hey, Alexandru, 
    Any lines in .../media-monitor/py-interpreter.log?
    Cloud Radio -> http://airtime.pro
  • None. It's empty.
  • Vote Up0Vote Down Cliff WangCliff Wang
    Posts: 339Member, Sourcefabric Team
    How about ../airtime/zendphp.log
    Cloud Radio -> http://airtime.pro
  • These are the kind on lines that appeared 1 day ago when it added some of the watched files
    2013-02-20T01:52:05+02:00 WARN (4): [StoredFile.php : setMetadata() : line 147] - using metadata that is not defined.
                            [MDATA_KEY_ORIGINAL_PATH] => [/store/psaltica/greceasca/Anghelopoulos/Antologie de Cantari - Patimile si Nasterea Domnului/15. Imn in Joia Mare.mp3]
    2013-02-20T01:52:05+02:00 WARN (4): [StoredFile.php : setMetadata() : line 147] - using metadata that is not defined.
                            [is_record] => []
    2013-02-20T01:52:05+02:00 WARN (4): [StoredFile.php : setMetadata() : line 147] - using metadata that is not defined.
                            [MDATA_KEY_ORIGINAL_PATH] => [/store/psaltica/romaneasca/Putna/03. Paraclisul/07. Stihirile.mp3]

    Now this is what I get when I refresh the watched folder

    2013-02-20T23:02:11+02:00 INFO (6): [LibraryController.php : indexAction() : line 62] - 2
    2013-02-20T23:02:11+02:00 INFO (6): [LibraryController.php : indexAction() : line 63] - playlist
    2013-02-20T23:02:11+02:00 INFO (6): [Playlist.php : getContents() : line 156] - Getting contents for playlist 2
    2013-02-20T23:17:57+02:00 INFO (6): [ApiController.php : rabbitmqDoPushAction() : line 837] - Notifying RabbitMQ to send message to pypo
    2013-02-21T00:10:55+02:00 INFO (6): [LibraryController.php : indexAction() : line 62] - 2
    2013-02-21T00:10:55+02:00 INFO (6): [LibraryController.php : indexAction() : line 63] - playlist
    2013-02-21T00:10:55+02:00 INFO (6): [Playlist.php : getContents() : line 156] - Getting contents for playlist 2
    2013-02-21T00:11:02+02:00 INFO (6): [PreferenceController.php : rescanWatchDirectoryAction() : line 418] - Unhiding all files belonging to:: /store/
    2013-02-21T00:11:04+02:00 INFO (6): [MusicDir.php : unhideFiles() : line 459] - unhide '1780' files
    2013-02-21T00:11:12+02:00 WARN (4): [StoredFile.php : setMetadata() : line 147] - using metadata that is not defined.
                            [MDATA_KEY_ORIGINAL_PATH] => [/store/predici/Pr. Cleopa - Predici vol. 3/17. Catacombele.mp3]
    2013-02-21T00:11:12+02:00 WARN (4): [StoredFile.php : setMetadata() : line 147] - using metadata that is not defined.
                            [is_record] => [0]
    2013-02-21T00:11:24+02:00 INFO (6): [LibraryController.php : indexAction() : line 62] - 2
    2013-02-21T00:11:24+02:00 INFO (6): [LibraryController.php : indexAction() : line 63] - playlist
    2013-02-21T00:11:24+02:00 INFO (6): [Playlist.php : getContents() : line 156] - Getting contents for playlist 2
    2013-02-21T00:13:42+02:00 INFO (6): [ScheduleController.php : eventFeedPreloadAction() : line 133] - agendaWeek
    2013-02-21T00:18:15+02:00 INFO (6): [LibraryController.php : indexAction() : line 62] - 1
    2013-02-21T00:18:15+02:00 INFO (6): [LibraryController.php : indexAction() : line 63] - stream
    2013-02-21T00:18:26+02:00 INFO (6): [StoredFile.php : uploadFile() : line 852] - /usr/share/airtime/application/models/StoredFile.php:uploadFile(): filename=p17jsqv6a662f1ksl1cr25l910qv4.mp3 to /tmp/plupload
    2013-02-21T00:18:26+02:00 INFO (6): [StoredFile.php : uploadFile() : line 852] - /usr/share/airtime/application/models/StoredFile.php:uploadFile(): filename=p17jsqv6a662f1ksl1cr25l910qv4.mp3 to /tmp/plupload
    2013-02-21T00:18:27+02:00 INFO (6): [StoredFile.php : uploadFile() : line 852] - /usr/share/airtime/application/models/StoredFile.php:uploadFile(): filename=p17jsqv6a662f1ksl1cr25l910qv4.mp3 to /tmp/plupload
    2013-02-21T00:18:27+02:00 INFO (6): [StoredFile.php : copyFileToStor() : line 945] - copyFileToStor: moving file /tmp/plupload/p17jsqv6a662f1ksl1cr25l910qv4.mp3
    2013-02-21T00:18:27+02:00 WARN (4): file_put_contents(/srv/airtime/organize/01. Cuvant in noaptea Sfintelor Pasti 1995.mp3.identifier): failed to open stream: Permission denied
    2013-02-21T00:18:27+02:00 INFO (6): [index.php : () : line 71] - file_put_contents(/srv/airtime/organize/01. Cuvant in noaptea Sfintelor Pasti 1995.mp3.identifier): failed to open stream: Permission denied
    2013-02-21T00:18:27+02:00 INFO (6): [index.php : () : line 73] - #0 [internal function]: exception_error_handler(2, 'file_put_conten...', '/usr/share/airt...', 990, Array)
    #1 /usr/share/php/libzend-framework-php/Zend/Log.php(598): call_user_func('exception_error...', 2, 'file_put_conten...', '/usr/share/airt...', 990, Array)
    #2 [internal function]: Zend_Log->errorHandler(2, 'file_put_conten...', '/usr/share/airt...', 990, Array)
    #3 /usr/share/airtime/application/models/StoredFile.php(990): file_put_contents('/srv/airtime/or...', 1)
    #4 /usr/share/airtime/application/controllers/PluploadController.php(44): Application_Model_StoredFile::copyFileToStor('/tmp/plupload', '01. Cuvant in n...', 'p17jsqv6a662f1k...')
    #5 /usr/share/php/libzend-framework-php/Zend/Controller/Action.php(516): PluploadController->copyfileAction()
    #6 /usr/share/php/libzend-framework-php/Zend/Controller/Dispatcher/Standard.php(295): Zend_Controller_Action->dispatch('copyfileAction')
    #7 /usr/share/php/libzend-framework-php/Zend/Controller/Front.php(954): Zend_Controller_Dispatcher_Standard->dispatch(Object(Zend_Controller_Request_Http), Object(Zend_Controller_Response_Http))
    #8 /usr/share/php/libzend-framework-php/Zend/Application/Bootstrap/Bootstrap.php(97): Zend_Controller_Front->dispatch()
    #9 /usr/share/php/libzend-framework-php/Zend/Application.php(366): Zend_Application_Bootstrap_Bootstrap->run()
    #10 /usr/share/airtime/public/index.php(64): Zend_Application->run()
    #11 {main}
    2013-02-21T00:18:42+02:00 INFO (6): [PreferenceController.php : rescanWatchDirectoryAction() : line 418] - Unhiding all files belonging to:: /store/
    2013-02-21T00:18:43+02:00 INFO (6): [MusicDir.php : unhideFiles() : line 459] - unhide '1780' files
    2013-02-21T00:18:50+02:00 INFO (6): [PreferenceController.php : rescanWatchDirectoryAction() : line 418] - Unhiding all files belonging to:: /store/
    2013-02-21T00:18:52+02:00 WARN (4): [StoredFile.php : setMetadata() : line 147] - using metadata that is not defined.
                            [MDATA_KEY_ORIGINAL_PATH] => [/store/predici/Pr. Cleopa - Predici vol. 3/17. Catacombele.mp3]
    2013-02-21T00:18:52+02:00 WARN (4): [StoredFile.php : setMetadata() : line 147] - using metadata that is not defined.
                            [is_record] => [0]
    2013-02-21T00:18:52+02:00 INFO (6): [MusicDir.php : unhideFiles() : line 459] - unhide '1780' files
    2013-02-21T00:19:00+02:00 WARN (4): [StoredFile.php : setMetadata() : line 147] - using metadata that is not defined.
                            [MDATA_KEY_ORIGINAL_PATH] => [/store/predici/Pr. Cleopa - Predici vol. 3/17. Catacombele.mp3]
    2013-02-21T00:19:00+02:00 WARN (4): [StoredFile.php : setMetadata() : line 147] - using metadata that is not defined.
                            [is_record] => [0]

    I also noticed this message two days ago. Now it's not in the logs aymore
    2013-02-19T10:43:59+00:00 INFO (6): [Preference.php : getValue() : line 134] - Could not connect to database: Unable to open PDO connection [wrapped: SQLSTATE[08006] [7] timeout expired]

    Also noticed this kind of messages in the pypo.log
    2013-02-18 23:33:21,352 ERROR - [listenerstat.py : get_stream_stats() : line 105] - Exception: HTTP Error 401: Authentication Required
    2013-02-18 23:33:21,545 DEBUG - [listenerstat.py : run() : line 131] - []
    2013-02-18 23:33:21,545 ERROR - [listenerstat.py : run() : line 134] - Not able to get listener stats
    2013-02-18 23:34:10,284 INFO - [replaygainupdater.py : run() : line 72] - Running replaygain updater
    2013-02-18 23:34:10,922 ERROR - [replaygainupdater.py : main() : line 67] - 'ReplayGainUpdater' object has no attribute 'unexpected_exception'
    2013-02-18 23:34:10,922 DEBUG - [replaygainupdater.py : main() : line 68] - Traceback (most recent call last):
      File "/usr/lib/airtime/pypo/bin/media/update/replaygainupdater.py", line 61, in main
        except Exception as e: self.unexpected_exception(e)
    AttributeError: 'ReplayGainUpdater' object has no attribute 'unexpected_exception'


    Any clue what's happening?
  • Vote Up0Vote Down Cliff WangCliff Wang
    Posts: 339Member, Sourcefabric Team
    Oh so did you change the storage folder to /srv/airtime?
    Please check the permission of that folder and make sure it looks like:
       drwxrwsr-x 6 root     www-data 4096 Feb  6 12:29 stor
    Cloud Radio -> http://airtime.pro
  • Ok...so... the permissions on the import folder /srv/airtime were wrong. When setting them as you told me it started to add to the library the uploaded files. But...this didn't happen for the watched folder.

    So I tried another thing. apt-get purge airtime, took the airtime 2.1 sources, made a full install, added the same folder with the same permissions and...in a couple of seconds it started to add the files to the library. I watched the process with the airtime-log command. After it finished it started to compute the replaygain for each file. The conclusion is that not because of permissions it doesn't add the files from the watched folder to the library.
    After I saw it's working I made an upgrade to airtime 2.3 and again... no files get added...and in point of replay gain computation - no way this will happen. It's like the media monitor doesn't tell zendphp or pypo to do the work...

    How can I help you to figure out what's happening?

    Alexandru
    Post edited by Alexandru Matei at 2013-02-21 15:16:55
  • Vote Up0Vote Down Cliff WangCliff Wang
    Posts: 339Member, Sourcefabric Team
    Hey,  Alexandru,

    I've gone through the media-monitor log you uploaded. And I found it said:
    "
    2013-02-20 15:29:04,912 INFO - [Thread-46] [request.py : run_request()] : LINE 54 - Request was successfult
    "
    It sounds like all files in /store are loaded in Library.

    So let's make it clear, can you please cp the contents in /store to another folder, and use command:
        sudo airtime-import --watch-add your_new_folder
    And see what's happening.
    Cloud Radio -> http://airtime.pro
  • I did what you said. After 20 minutes it started to add them to the library. And now it computes the replay gain values. Is this normal? On another host, I tried to add a watched folder last night and it started to add them after some hours. Is this the normal behavior?!?

    Also, another issues encountered. I wanted to have the original vhost configuration shipped with the installer. So I did a dpkg-reconfigure airtime ... and the vhost file got in his place and I got a message about the symlink to liquidsoap not beeing in the right place. After some time I noticed that all the processes were down...and the file /etc/airtime/liquidsoap.cfg was missing. I did another reconfigure with dpkg and the file appeared again. Still, the playout won't start. After some 'debugging' I found out that the starting script tried to access /usr/bin/airtime-liquidsoap, a symlink to the missing /usr/bin/liquidsoap. Since I compiled my own liquidsoap to have aacp the file is in /usr/local/bin/liquidsoap. After restablishing the links the playout engine started.

    Alexandru
  • Vote Up0Vote Down Cliff WangCliff Wang
    Posts: 339Member, Sourcefabric Team
    20 minutes is a little bit long as importing  about 1000 files, how's your cpu and ram settings on that machine?

    About liquidsoap soft link, you're right that you need to point /usr/bin/airtime-liquidsoap to correct file if you replace the default one.
    Post edited by Cliff Wang at 2013-02-22 15:29:58
    Cloud Radio -> http://airtime.pro
  • Is a Pentium D at 2,8Ghz an 1GB of RAM...but I think I wasn't clear.

    After 20 min it started to do some action.

    After the cmd to add the watched folder issued at 19:20

    2013-02-22 19:00:08,435 INFO - [Thread-5] [airtime.py : handle_message()] : LINE 54 - Received md from RabbitMQ: {"directory":"\/test","event_type":"new_watch"}
    2013-02-22 19:00:08,435 INFO - [Thread-5] [airtime.py : message()] : LINE 84 - Handling RabbitMQ message: 'new_watch'
    2013-02-22 19:00:08,436 INFO - [Thread-5] [airtime.py : new_watch()] : LINE 131 - Creating watch for directory: '/test'
    2013-02-22 19:00:08,870 INFO - [Thread-5] [owners.py : get_owner()] : LINE 12 - Received owner for /test/predici/IPS Bartolomeu - Octoih/Predica la Duminica 25 dupa Rusalii - 2000.mp3. Owner: -1
    2013-02-22 19:00:08,871 INFO - [Thread-5] [events.py : __init__()] : LINE 96 - did not match path: /test/predici/IPS Bartolomeu - Octoih/Predica la Duminica 25 dupa Rusalii - 2000.mp3
    2013-02-22 19:00:08,872 INFO - [Thread-5] [watchersyncer.py : handle()] : LINE 65 - Received event 'ModifyFile'. Path: '/test/predici/IPS Bartolomeu - Octoih/Predica la Duminica 25 dupa Rusalii - 2000.mp3'
    2013-02-22 19:00:08,872 INFO - [Thread-5] [watchersyncer.py : push_queue()] : LINE 97 - Added event into queue

    The last lines repeat for all the files in /test, and then it finishes with this lines

    2013-02-22 19:00:09,391 INFO - [Thread-5] [bootstrap.py : flush_watch()] : LINE 63 - Flushed watch directory (/test).                 (added, modified, deleted) = (84, 84, 0)
    2013-02-22 19:00:09,391 INFO - [Thread-5] [manager.py : add_watch_directory()] : LINE 210 - Adding watched directory: '/test'
    2013-02-22 19:00:09,391 INFO - [Thread-5] [manager.py : __add_watch()] : LINE 99 - Attempting to add listener to path '/test'
    2013-02-22 19:00:09,391 INFO - [Thread-5] [manager.py : __add_watch()] : LINE 100 - Listener: Listener(StoreWatchListener), Signal(hosted_install_watch)
    2013-02-22 19:00:10,286 INFO - [Thread-3] [watchersyncer.py : run()] : LINE 39 - We have 168 events that are unflushed
    2013-02-22 19:00:10,286 INFO - [Thread-3] [watchersyncer.py : flush_events()] : LINE 107 - Force flushing events...
    2013-02-22 19:00:10,286 INFO - [Thread-3] [watchersyncer.py : push_request()] : LINE 146 - WatchSyncer : Unleashing request
    2013-02-22 19:00:10,287 INFO - [Thread-8] [request.py : run_request()] : LINE 34 - Attempting request with 168 items.
    2013-02-22 19:21:39,907 INFO - [Thread-8] [api_client.py : send_media_monitor_requests()] : LINE 295 - Pumping out 168 requests...
    2013-02-22 19:21:47,202 INFO - [Thread-8] [request.py : run_request()] : LINE 54 - Request was successful

    As you can see for 20 min it was "sleeping".....zzZZZzzzZZZ and then it decides to pump the requests.

    And in the pypo.log I can see that after 1-2 min it started to compute the reaplygain.
    2013-02-22 19:23:06,493 INFO - [replaygain.py : duplicate_file() : line 43] - Copying /test/predici/IPS Bartolomeu - Octoih/Predica la Duminica 18 dupa Rusalii - 2005.mp3 to /tmp/tmpSblY86
    2013-02-22 19:23:06,604 DEBUG - [replaygain.py : get_process_output() : line 16] - nice -n 15 mp3gain -q "/tmp/tmpSblY86" 2> /dev/null

    Thanks.
  • Vote Up0Vote Down Cliff WangCliff Wang
    Posts: 339Member, Sourcefabric Team
    Ok I see, it ought not to be so long... Can I ask what kind of files in your watched folder, all mp3 or some other types?
    Cloud Radio -> http://airtime.pro
  • All mp3. The files are the same as used with airtime 2.1 and there were no problems with that version. And...this ones from the test folder got added...finally to the library but the ones from the original watched folder, why not?

    Alexandru
  • Vote Up0Vote Down Cliff WangCliff Wang
    Posts: 339Member, Sourcefabric Team
    I guess those are already in the database but set as "not exists" in cc_files table. Just simply check the column "file_exist" of cc_files if it's "f".
    Cloud Radio -> http://airtime.pro
  • Vote Up0Vote Down Cliff WangCliff Wang
    Posts: 339Member, Sourcefabric Team
    BTW, Can you try to link /usr/bin/airtime-liquidsoap back to default /usr/bin/liquidsoap and import files again? Kind of wandering if the liquidsoap file check takes too long in your instance.
    Just you don't have it, just run:
    sudo apt-get install liquidsoap
    then replace soft link and restart airtime-liquidsoap service.
    Cloud Radio -> http://airtime.pro
  • Vote Up0Vote Down Cliff WangCliff Wang
    Posts: 339Member, Sourcefabric Team
    Can you share the PACKAGES file for liquidsoap compiling? I would like to try it on my machine. 
    Cloud Radio -> http://airtime.pro
  • for the database table: yes, the file_exists if 'f' for the files not added to the library.

    I linked the /usr/bin/liquidsoap to the one which installed from the ubuntu repo. liquidsoap - 1.0.1. Restarted liquidsoap. Copied the /store to another dir, added it as watched folder and... nothing. Every 3 secs I get this line in the log

    2013-02-23 00:21:54,289 INFO - [Thread-3] [watchersyncer.py : run()] : LINE 34 - We have 1 requests waiting to be launched

    Another thing. Every time I rescan a watched folder there are messages in the zendphp.log regarding some files I deleted once. But nothing about the ones that exist there...

    Regarding the packages file...there is none. I forgot from where/how I compiled the liquidsoap source. Do you think is important?

    Alexandru

    P.S. As  I finished editing this message the files from the new added folder got added to the library after a "sleep" of 10 minutes. But not the ones from the initial store, those marked as "not exist".
  • I manually dumped the airtime database. Reinstaled. No change.
    Did you noticed anything strange?

    Then I downgraded to airtime 2.1 and everything works as expected. Same machine, same liquidsoap. It has to be something with media-monitor. I'm sure it changed between this versions because even the messages for replay gain go in different log files.

    Alexandru
  • Vote Up0Vote Down Cliff WangCliff Wang
    Posts: 339Member, Sourcefabric Team
    Could you please use 'sudo airtime-log' to dump all logs and upload to here? If you still have 2.3's log.
    Cloud Radio -> http://airtime.pro
  • Vote Up0Vote Down Cliff WangCliff Wang
    Posts: 339Member, Sourcefabric Team
    Hey, Alexandru,
    I'm wondering the following steps can fix your problem:
    "
    sudo apt-get remove silan
    "
    That will disable track silence detection.
    Cloud Radio -> http://airtime.pro
  • This strange behavior appeared on two servers. One with ubuntu 12.04 which is on it's road to a datacenter and on one with ubuntu 10.04. I'll try your solutions on this second server. Coming back shortly.
  • Ok...Had to do a force removal to get rid of silan. It's a dependency for airtime, so by default apt removes also airtime.

    I stopped all the processes: monit, rabbitmq, postgresql, playout, liquidsoap, media-mon.... Then did a
    dpkg -r  --ignore-depends=airtime silan
    After that started everything...and, thanks God, instantly it started adding files to the library. Now it's computing the replaygain values. I'm not able yet to see any in the column from the library even if it computed some, but I hope them to appear. Is this ok?
    While adding the files to the library the logs where highly injected with lines reporting silan is missing.

    Since now everything seems to work as expected. Waiting for replaygain to appear in the library.

    Alexandru