Media-monitor and SFTP uploads problem - Airtime Support Discussions on Sourcefabric Forum

Sergei S.

A file uploaded by FTP to a folder inside a watched one does not appear in AirTime searches.
/var/log/airtime/media-monitor/media-monitor.log is filled with repeating blocks like this:

2011-09-19 20:06:21,217 INFO - [MainThread] [airtimeprocessevent.py : process_IN_MODIFY()] : LINE 83 - process_IN_MODIFY: <Event dir=False mask=0x2 maskname=IN_MODIFY name=aleceed.mp3 path=/music/rubriki/realnyrazgovor pathname=/music/rubriki/realnyrazgovor/aleceed.mp3 wd=1196 >
2011-09-19 20:06:21,217 INFO - [MainThread] [airtimeprocessevent.py : handle_modified_file()] : LINE 88 - Modified: /music/rubriki/realnyrazgovor/aleceed.mp3
2011-09-19 20:06:21,218 INFO - [Thread #0] [workerprocess.py : process_file_events()] : LINE 9 - received event {'mode': 'modify', 'filepath': '/music/rubriki/realnyrazgovor/aleceed.mp3'}
2011-09-19 20:06:21,218 INFO - [Thread #0] [airtimenotifier.py : update_airtime()] : LINE 134 - updating filepath: /music/rubriki/realnyrazgovor/aleceed.mp3 
2011-09-19 20:06:21,218 INFO - [Thread #0] [airtimemetadata.py : get_md_from_file()] : LINE 120 - getting info from filepath /music/rubriki/realnyrazgovor/aleceed.mp3
2011-09-19 20:06:21,239 INFO - [Thread #0] [airtimemetadata.py : get_md_from_file()] : LINE 135 - {'encodedby': [u'AIMP2'], 'tracknumber': [u'03']}
2011-09-19 20:06:21,393 INFO - [Thread #2] [api_client.py : update_media_metadata()] : LINE 417 - update media {"error":"File does not exist in Airtime."}, filepath: /music/rubriki/realnyrazgovor/aleceed.mp3, mode: modify
2011-09-19 20:06:21,393 INFO - [Thread #2] [api_client.py : update_media_metadata()] : LINE 421 - time taken to get response 5.13294291496
2011-09-19 20:06:21,402 INFO - [Thread #0] [api_client.py : update_media_metadata()] : LINE 417 - update media {"error":"File does not exist in Airtime."}, filepath: /music/rubriki/realnyrazgovor/aleceed.mp3, mode: modify
2011-09-19 20:06:21,402 INFO - [Thread #0] [api_client.py : update_media_metadata()] : LINE 421 - time taken to get response 0.161731004715

AirTime 1.9.2, Ubuntu

Martin Konecny

Hi Sergei. Are you saying this only happens with FTP? What happens if you copy the file into that folder using basic copy or move commands like "cp" or "mv"?

Sergei S.

Hello Martin,
After first failure with FTP I moved the file up one level and then back with 'mv';
touch'ed it, and changed owner/group a couple of times -- no luck.
As the show was up soon, I used "airtime-import -m" to import the file to AirTime and put it on scheduled show.

Martin Konecny

Could you attach the entire log file. From what you provided, the file is being modified and this new information is being sent to the Airtime server, but it looks like the Airtime server was never aware the file existed in the first place. So may be some error related to when the file was first created.

Sergei S.

Attached to this message is the complete log.
However, the first lines aren't any special:

2011-09-19 20:05:42,655 INFO - [MainThread] [airtimeprocessevent.py : process_IN_MODIFY()] : LINE 83 - process_IN_MODIFY: <Event dir=False mask=0x2 maskname=IN_MODIFY name=aleceed.mp3 path=/music/rubriki/realnyrazgovor pathname=/music/rubriki/realnyrazgovor/aleceed.mp3 wd=1196 >
2011-09-19 20:05:42,655 INFO - [MainThread] [airtimeprocessevent.py : handle_modified_file()] : LINE 88 - Modified: /music/rubriki/realnyrazgovor/aleceed.mp3
2011-09-19 20:05:42,656 INFO - [Thread #3] [workerprocess.py : process_file_events()] : LINE 9 - received event {'mode': 'modify', 'filepath': '/music/rubriki/realnyrazgovor/aleceed.mp3'}
2011-09-19 20:05:42,656 INFO - [Thread #3] [airtimenotifier.py : update_airtime()] : LINE 134 - updating filepath: /music/rubriki/realnyrazgovor/aleceed.mp3 
2011-09-19 20:05:42,656 INFO - [Thread #3] [airtimemetadata.py : get_md_from_file()] : LINE 120 - getting info from filepath /music/rubriki/realnyrazgovor/aleceed.mp3
2011-09-19 20:05:42,665 INFO - [Thread #3] [airtimemetadata.py : get_md_from_file()] : LINE 135 - {'encodedby': [u'AIMP2'], 'tracknumber': [u'03']}
2011-09-19 20:05:42,799 INFO - [Thread #3] [api_client.py : update_media_metadata()] : LINE 417 - update media {"error":"File does not exist in Airtime."}, filepath: /music/rubriki/realnyrazgovor/aleceed.mp3, mode: modify
2011-09-19 20:05:42,799 INFO - [Thread #3] [api_client.py : update_media_metadata()] : LINE 421 - time taken to get response 0.132598876953

Martin Konecny

Ok you're right, they're all the same lines.

Could you post the file up for download temporarily someplace, so I can try to recreate this problem?

Sergei S.

Martin,

here's the link: aleceed.mp3 ( 50Mb mp3)

Martin Konecny

Thanks got it.

Initial try didn't show anything wrong. Perhaps copying over ftp does something different. What ftp server did you use?

Sergei S.

It is actually an SFTP connection to a Ubuntu box.
How can I check for the SFTP server version?

Martin Konecny

Try

dpkg -l | grep ftpd-ssl

If that shows something, you are probably using that package.

Sergei S.

Hi Martin,
the command didn't show any output, however these might help:

ii  openssh-client                  1:5.5p1-4ubuntu5                  secure shell (SSH) client, for secure access to remote machines
ii  openssh-server                  1:5.5p1-4ubuntu5                  secure shell (SSH) server, for secure access from remote machines
ii  openssl                         0.9.8o-1ubuntu4.4                 Secure Socket Layer (SSL) binary and related cryptographic tools

A few new notes: I was uploading a new file by SFTP and noticed a high CPU usage by python while the upload was running; also a new bunch of log records in media-monitor.log are related to this timespan.
Lots of lines per sec, like these:

2011-09-21 19:00:00,072 INFO - [Thread #3] [workerprocess.py : process_file_events()] : LINE 9 - received event {'mode': 'modify', 'filepath': '/home/pypo/music/rubriki/strategzapas/strt zapas neyro 3.mp3'}
2011-09-21 19:00:00,072 INFO - [Thread #3] [airtimenotifier.py : update_airtime()] : LINE 134 - updating filepath: /home/pypo/music/rubriki/strategzapas/strt zapas neyro 3.mp3 
2011-09-21 19:00:00,072 INFO - [Thread #3] [airtimemetadata.py : get_md_from_file()] : LINE 120 - getting info from filepath /home/pypo/music/rubriki/strategzapas/strt zapas neyro 3.mp3
2011-09-21 19:00:00,101 INFO - [Thread #3] [airtimemetadata.py : get_md_from_file()] : LINE 135 - {'encodedby': [u'AIMP2'], 'tracknumber': [u'03']}
2011-09-21 19:00:00,240 INFO - [Thread #3] [api_client.py : update_media_metadata()] : LINE 417 - update media {"error":"File does not exist in Airtime."}, filepath: /home/pypo/music/rubriki/strategzapas/strt zapas neyro 3.mp3, mode: modify

I suspect that airtime-media-monitor considered the file was constantly updated while it was uploading, and that overloaded the system.

Also, after the upload finished the file didn't appear in AT database, until I restarted the airtime-media-monitor service -- guess the service halted during that crazy minutes of file upload.

Daniel James

Hi Sergei, what you need to do is upload by SFTP to a temporary directory such as:

/srv/airtime/uploads/incoming/

then run the airtime-import script on that directory. Otherwise the media-monitor will be trying to handle partial files, as you suggest. The full details are here:

http://en.flossmanuals.net/airtime/automated-file-import/

Cheers!

Daniel

Martin Konecny

That's what I was afraid of. Wasn't sure how FTP transferred files, but looks like it keeps appending and closing it, which confuses media-monitor, since it never knows for sure when the file has completed.

Daniel James

Another tip: if you upload by scp to the temporary directory, you can then script an ssh command to force an immediate airtime-import, rather than waiting for an hourly cron job. You would need to handle the ssh authentication in an automated way, perhaps using a strong key pair without a passphrase.

Daniel James

Hi Martin, we actually want media-monitor to reject partial files, because if copy to the watched folder fails to complete for any reason, the partial file could end up in a playlist. The user might not audition the whole file before playout.

We also need airtime-import to reject partial files, can it do that at present?

Sergei S.

Daniel, thanks for the replies!

Tmp folder / mv is not user-freindly enough for our editors, no so techy nice people.

What about DropBox? I could set up DropBox shared folder to contain frequently updated files like News and announces. Did anyone try Dropbox + AirTime Media Monitor?

Martin Konecny

Haven't tried Dropbox, but it would be interesting if you tried it out and let us know. Should be as simple as adding a watched folder to a Dropbox subfolder and see what happens when syncing Smile

.

Martin Konecny

Daniel,

It was rejecting partial files, although not elegantly, because it couldnt read the id3 tag until much later. Later when it could read the tag, it was telling the server to update information about the file, but since the "create" command to the server never happened, the "update" commands to the server didn't do anything.

I think it's hard to detect whether an audio track is partial or complete. If the id3 tags are available (in id3v2 they are at the beginning of the file), then how do we know where it's supposed to end? Perhaps there is a way to do this, but I'd have to research it.

Sergei S.

Martin Konecny писал(а) Ср., 21 Сентябрь 2011 20:10

Haven't tried Dropbox, but it would be interesting if you tried it out and let us know

Installed and tryed. Should be a perfect solution, as Dropbox syncs files to a hidden .dropbox.cache folder, and only after completion moves it to the destination folder.

However I experienced problems adding a sub-folder to Watched folders of AT, which gives an error:
'/home/user/Dropbox/AbbeyRoad/' is not a valid directory.

Nevertheless, the parent folder, 'Dropbox' itself, was added to AT without such an error.

Need a little help with permissions here. I have set both 'Dropbox' and 'Dropbox/AbbeyRoad' same permissions: u:rwx g:rwx,
and assigned the group to be the one that I use for users related to the radio. How comes that Dropbox is ok for AT, and Dropbox/AbbeyRoad is not?

Daniel James

Hi Martin,

How about we read the length from the id3 tag, and reject the import of the file if the length doesn't match within 1 second of what the tag says it should be?

I know that some length tags are not correct, but if so they are going to be a problem for the Playlist Builder anyway.

Cheers!

Daniel

Sergei S.

Daniel, Martin,
maybe not the best one, but what if check file'z size, then timeout for 2 seconds, then check it again - if not changed - maybe it finished uploading, or.. just internet connection was dropped.

Ed Porras

We're using Dropbox on 1.8.2 (so no watched folder available). What I do is
run a script once a minute (using cron) to look for files and import them if
available. The only issue we've ran into is sometimes Dropbox creates
0-length files when the file is first dropped on the remote server. Once the
file is fully available, then it is updated to the full length.

I worked around it by simply importing only if it's not a 0-length file. :)

I'd like to switch to 1.9.x soon but have seen several problems reported and
we're live so I can't do it until I'm sure enough there won't be a major
issue causing us to go off-air.

-e
--
Ed Porras | http://www.digressed.net/

Daniel James

Hi Ed,

I would recommend running a test server in parallel to your production system. Airtime 1.9.4 has been through a lot of QA including fixing a number of bugs that were in 1.8.2, but even so I would still recommend running a dummy upgrade with a copy of your existing database and storage before doing it for real on the production server.

Cheers!

Daniel

Howdy, Stranger!

Categories

Poll

Top Posters