lazy or nonworking media-monitor - Airtime Support Discussions on Sourcefabric Forum

Alexandru Matei

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

Alexandru Matei

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

Cliff Wang

Hey, Alexandru,

Any lines in .../media-monitor/py-interpreter.log?

Alexandru Matei

None. It's empty.

Cliff Wang

How about ../airtime/zendphp.log

Alexandru Matei

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: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?

Cliff Wang

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

Alexandru Matei · Post edited by Alexandru Matei at 2013-02-21 15:16:55

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

Cliff Wang

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.

Alexandru Matei

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

Cliff Wang · Post edited by Cliff Wang at 2013-02-22 15:29:58

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.

Alexandru Matei

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.

Cliff Wang

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?

Alexandru Matei

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

Cliff Wang

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".

Cliff Wang

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.

Cliff Wang

Can you share the PACKAGES file for liquidsoap compiling? I would like to try it on my machine.

Alexandru Matei

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".

Alexandru Matei

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

Cliff Wang

Could you please use 'sudo airtime-log' to dump all logs and upload to here? If you still have 2.3's log.

Cliff Wang

Hey, Alexandru,

I'm wondering the following steps can fix your problem:

"

sudo apt-get remove silan

"

That will disable track silence detection.

Alexandru Matei

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.

Alexandru Matei

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

Howdy, Stranger!

Categories

Poll

Top Posters