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
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.
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.
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)
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
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
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.
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] [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
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?
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".
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.
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.
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.