deny-agents does not work

[art1c0]

It seems that "deny-agents" feature isn't working in 2.3.3. Is there any substitute for this or how to make it work? It was one of the main reasons to switch my radio to icecast-kh.

[karlheyes]

seems to be working for me, there's been no recent changes affecting the code for that. Maybe some log information and xml can shed some light?

karl.

[art1c0]

ok, so I have added this line into paths section of icecast.xml:

<deny-agents>/usr/local/etc/icecast.deny-agents</deny-agents>

then in this file I have only one line (just for test):

*VLC*

when I try to listen with VLC player I have this in the access log:

"GET /channel32kAAC HTTP/1.1" 200 191089 "-" "VLC/2.0.6 LibVLC/2.0.6" 32

I can listen as usual and nothing in error log.

[karlheyes]

can you say which precise build it is. You should see in the error log lines line

[2014-05-24 20:33:48] INFO connection/recheck_cached_file 1 entries read from file "...."

karl.

[art1c0]

"icecast -v" gives me this:

Icecast 2.3.3-kh10-20140524200615

and I don't have such lines in the error log. all I have is lines like this:

INFO source/source_read listener count on /channel.32k.aac now 1

[karlheyes]

Check for any error messages as well, in cases of file access problems or missing file, but if that file is being read then that recheck_cached_file will appear and report the number of entries from it. If it does not appear then either the tag is missing or the file cannot accessed for some reason.

eg [2014-05-25 18:21:44] WARN connection/recheck_cached_file failed to check status of "agents.missing": No such file or directory

note that the cached file checks are triggered on incoming requests, so getting the status page will be enough to cause it to happen.

karl.

[art1c0]

I tried to supply invalid file path, just added an extra "s" to the existing one. After that I have following record in error log:

WARN connection/recheck_cached_file failed to check status of "/usr/local/etc/icecast.deny-agentss": No such file or directory

So it means, that previously agents file was accessible, as I didn't have such error before.

Also I added a few more entries to the file, to check with different players - still no result, stream is playable with no problem, and I don't have any corresponding lines in error log, as well as any "recheck_cached_file" entries.

Additionally I did "chmod 0777" with that file - the same result. Although it was readable by any user before.

[karlheyes]

try chmod 000 .... and see if you get the failed to open file message, if that works but you still get no other messages with the file readable then that would be odd as there are no other exit paths without the entries count being logged. In such a case then a remote ssh would be needed to see what is happening.

karl.

[art1c0]

I tried chmod 000 and have no error messages.

[karlheyes]

ok, that is an odd one. No messages for a 'permission denied' case would indicate an issue with the modification time on the file, or more specifically that it does not seem to change. You can use the 'stat' command to see the timestamps on the file, can be verify whether the modify time is actually changing when you update the file. If it is then it's puzzling, and I'll definitely need ssh to check it.

karl.

[art1c0]

I checked stat command on that file, and dates are changing when the file is changing. So it's working okay. Moreover, I've been restarting icecast every time when testing this before, to be sure that this is not the case. I guess the file is being re-read every time upon restart. So I don't think that this can be a reason. Problem is NOT that the file changes are not seen, problem is that this file is seems to be ignored at all. Icecast only sees when the file is missing, but doesn't see its contents. Unfortunately I cannot provide you SSH access to the server, as it is a live server with live listeners, and I don't have such privilieges, sorry.

[karlheyes]

the code is specifically done to avoid unnecessary reads but relies on a modified timestamp changing or else it will skip. The fact that you managed to get a 'no such file' message means that you are getting into the routine you need to, but the fact that the chmod 000 is not causing a permission denied/access denied message would tend to indicate that the modification time is not being updated, or at least what we are getting back is not changing.

The same routine is used for banned IPs so that would indicate that banned IPs is also broken. What can you tell me about the OS and FS used?

karl.

[art1c0]

Am I right that these files are being re-read upon daemon restart? If yes, then it's not about file changes, as I didn't see deny-agents working even once, from the very beginning, and I restarted the server each time after modifications. OS is FreeBSD, filesystem is ufs.

[art1c0]

I did some research about stat comand in my system, and this is what I found, maybe it could help. In the output of stat command I have four dates: The time file was last accessed or modified, or when the inode was last changed, or the birth time of the inode (st_atime, st_mtime, st_ctime, st_birthtime). So after the file's content modification, both dates (st_mtime, st_ctime) are changing. But after chmod - only one date is changing (st_ctime). st_mtime remains the same. This article is explaining stat command difference between Linux and FreeBSD, maybe this is the reason: http://npre.wordpress.com/2012/08/31/linux-like-stat-in-freebsd/

[karlheyes]

The trigger is when a request comes in, if there are no incoming requests then it does not consider it, so getting the status page would be enough. There has to be at least 10 seconds since the last check and each check involves the modification time and if that has been updated then the file is opened. You are correct in that chmod is not expected to change the mtime so you can just use touch or re-save the content to update the mtime (it may be FS dependent)

karl.

[art1c0]

I was re-saving the file all the times (this updates mtime), that was your idea to try chmod. So it's still not working. The file is accessible, no errors in the log, listed agents are allowed to read the stream.

[art1c0]

I have just checked it now and I finally noticed this line in the log:

INFO connection/recheck_cached_file 2 entries read from file "/usr/local/etc/icecast.deny-agents"

but agents stil can access the stream. Why can it be so?

[karlheyes]

what are the 2 entries? I do log the agent in the access log. remember there's about 10 seconds to elapse before each checkup and only on a new request, using curl is a simple trigger for this sort of thing.

karl.

[art1c0]

entries are

*streamWriter*
*VLC*

and I was waiting more than 10 seconds. actually it's triggering instantly as we always have listeners coming and going. Just checked it again with VLC player and I have this line in access log:

"GET /ilma64kAAC HTTP/1.1" 200 155157 "-" "VLC/2.0.6 LibVLC/2.0.6" 12

[karlheyes]

actually I found the issue now, it's not a reading issue, but an ordering issue in the internal storage created because of the wildcards. explicit strings should be fine. looking into it

karl.

[art1c0]

great! waiting for the solution

[art1c0]

any news?

[karlheyes]

finally got around to this, I've just uploaded fixes for that. The issue was for IPs as well as for useragents so took some time to get some sane API worked out.

karl.

[art1c0]

Karl, I just recompiled and checked the updated app - it does not seem to be working still.

icecast -v
Icecast 2.3.3-kh10-20140604031350

cat /var/log/icecast/error.log | grep "connection/recheck_cached_file"
[2014-06-04  03:14:30] INFO connection/recheck_cached_file 2 entries read from file "/usr/local/etc/icecast.deny"
[2014-06-04  03:14:30] INFO connection/recheck_cached_file 2 entries read from file "/usr/local/etc/icecast.deny-agents"

cat /usr/local/etc/icecast.deny-agents
*streamWriter*
*VLC*

I can listen to stream with VLC player:

[04/Jun/2014:03:21:35 +0300] "GET /ilma64kAAC HTTP/1.1" 200 88045 "-" "VLC/2.0.6 LibVLC/2.0.6" 3

[karlheyes]

just updated for a possible initialisation bug. The vlc test here works but you could report the log in more detail such as all the "connection/" lines at level 4.

karl.

[art1c0]

Karl. It's still not working. Could you please check on your side before reporting that it is fixed? Below I provide all log entries with "connection/" as you asked:

[2014-06-05  08:45:56] INFO connection/connection_thread connection thread started
[2014-06-05  08:45:56] INFO connection/get_ssl_certificate No SSL capability on any configured ports
[2014-06-05  08:45:56] INFO connection/recheck_cached_file 2 entries read from file "/usr/local/etc/icecast.deny"
[2014-06-05  08:45:56] INFO connection/search_banned_ip removing ..... from ban list for now
[2014-06-05  08:45:56] INFO connection/search_banned_ip removing ..... from ban list for now
[2014-06-05  08:45:56] INFO connection/recheck_cached_file 2 entries read from file "/usr/local/etc/icecast.deny-agents"
[2014-06-05  08:45:57] INFO connection/_handle_source_request Source logging in at mountpoint "/ilma.64k.aac"

[art1c0]

Also after seeing this line in the log

INFO connection/search_banned_ip removing ...my_ip... from ban list for now

I checked whether the IP filter also works - it does not. I can listen from my IP, from VLC player - both IP and VLC are banned. File was re-read after I added my IP there, there is a log entry about that. Could you please explain what does this mean: "removing ...ip... from ban list for now" and why it happens?

[karlheyes]

I reported that I had updated the code that fixes the out of order issue, which it does do, and I checked that here and it works as expected.

The key issue that looks to be occurring is the removal messages, this is why detailed information and not fragments can be important. Looks to be getting triggered from an related option for dynamic banning of IPs based on the request they make, eg 3600 in to block that address for an hour. The selection for IP removal code was still considering static ones if it came across them in the internal structure. It's actually a separate bug but in the same code.

This only affects banned IPs not banned useragents.

karl.

[art1c0]

Thank you Karl. I would like not to go too deep into Icecast details, as I'm not in this code at all, I just found a few issues in your project and trying to help you, other users and me as well, as I am your application user. So could you please let me know when user-agents filtering is working, and when ip-filtering is working also, please check that on your side - then I can recompile app on my side and will let you know the real results. Again, I'm on a live environment, it's working radio, so I don't really like to recompile and check that it's not working indeed, which happened already two times. Thanks again. Waiting for information from you.

[art1c0]

Hello Karl! Any news about the issue?

[art1c0]

Hi Karl, May I ask you, are you going to fix this issue? It's more than two months gone after your latest comment... I understand, it's an open-source project, but still it would be very nice to have this feature working as expected. Thank you

[karlheyes]

That particular issue was resolved. When I get my latest non-icecast related work sorted out then I'll be doing a release.

karl.

[gunsar]

in latest version kh16, deny-agents still not working properly