KH 14 Not Rotate Logs (Centos 7)

[edinsof]

Hi Any change on new icecast kh release (Icecast 2.4.0-kh14)? I'm currently have icecast kh on centovacast and when centova rotate logs to: access.log access.log.1 access.log.2 access.log.3 last icecast release dont reopen files for add logs

i have another centovacast server running Icecast 2.4.0-kh13 and works fine

2 servers has centovacast and centos 7

[edinsof]

maybe is a same problem that #189 ?

[karlheyes]

try the latest master build to verify. Some log issues were resolved which depended on the precise log settings used.

karl.

[edinsof]

I'm using the latest master build now and issue still continues

[karlheyes]

let me know what you have for your xml settings, in relation to logging. The numbered sequence is probably done by logrotate on centos. A reload event should be triggering a re-open but it sounds like you are saying that the reload/HUP is not happening

karl.

[edinsof]

access.log error.log playlist.log 1

[karlheyes]

the xml tag handling when posting is indeed quirky when posting. So you are logging bare bones info, rotating with logrotate/reload and what, the rotation is not happening? When icecast itself does the rotation then you eitheer have .old or .date_xxx format for named old files, ususally trigger on filesize. logrotate uses the rename and reload method which is when you get the .1 type of name. So the question is what are you expecting and what is happening?

karl.

[edinsof]

Logs are rotating but empty files.

[karlheyes]

strange. Obviously at level 1 then there won't be much to log in the error log but the access log should have entries even if they are 404 responses. I would firstly check to see if the filename ties in with the opened file so check the following

lsof -nPp pidof icecast | grep log

It it is deleted then it may be that logrotate is replacing the log icecast is using with an empty one which is then rotated later. icecast will create the file as needed so use the nocreate option in logrotate, maybe notifempty as well.

karl.

[edinsof]

I change log level to 4

and can see [2020-06-24 03:12:25] INFO logging/recheck_log_file Using log file var/log//access.log [2020-06-24 03:12:25] INFO logging/recheck_log_file Using log file var/log//playlist.log see double / Maybe this is the error ?

[karlheyes]

not usually a problem, the parsing typically handles that in the caes I have seen. Check the lsof output first, see what the reference icecast has for the log and see if it referring to a deleted file. It may something else like icecast being prevented from opening the log, although a version update of icecast should not change that.

karl

[edinsof]

[root@localhost~]# lsof -nPp '11386' | grep log icecast 11386 ccuser 13w REG 9,1 7521880 7602178 /usr/local/centovacast/var/vhosts/demo/var/log/access.log.1 icecast 11386 ccuser 20w REG 9,1 51 7602179 /usr/local/centovacast/var/vhosts/demo/var/log/playlist.log.1 [root@localhost ~]#

[edinsof]

Icecast continues writing on (access.log.1 and playlist.log.1) but Don't on (access.log and playlist.log) files

[edinsof]

[root@localhost ~]# lsof -nPp '11386' | grep log icecast 11386 ccuser 13w REG 9,1 7936066 7602178 /usr/local/centovacast/var/vhosts/demo/var/log/access.log.2 icecast 11386 ccuser 20w REG 9,1 51 7602179 /usr/local/centovacast/var/vhosts/demo/var/log/playlist.log.2 [root@localhost ~]#

Icecast continues writing on (access.log.2 and playlist.log.2) but Don't on (access.log and playlist.log) files

[karlheyes]

yes, that would indicate the move/rename is being done but the reload/HUP is not being done properly. Interesting to note that you have no error log in that lsof list, a 0 byte error.log file but 2 log entries about rechecking the access and playlist files. Something seems inconsistent. If you "killall -HUP icecast", what happens if anything, and why there is no error log being written to at level 4.

karl.

[edinsof]

Sorry. I back log level to 1

[edinsof]

Last lines on error.log (level 4)

[2020-07-05 04:53:37] DBUG stats/stats_global_calc update global outgoing_kbitrate (5070) [2020-07-05 04:53:37] DBUG stats/stats_global_calc update global stream_kbytes_read (487710) [2020-07-05 04:53:37] DBUG stats/stats_global_calc update global stream_kbytes_sent (17278707) [2020-07-05 04:53:38] INFO connection/wait_for_serversock HUP received, reread scheduled [2020-07-05 04:53:38] INFO event/event_config_read Re-reading XML [2020-07-05 04:53:38] WARN xml/parsing warning:

[root@localhost ~]# lsof -nPp '10067' | grep log icecast 10067 ccuser 11w REG 9,1 7664982 7602562 /usr/local/centovacast/var/vhosts/demo/var/log/error.log icecast 10067 ccuser 14w REG 9,1 2716750 7602179 /usr/local/centovacast/var/vhosts/demo/var/log/access.log.1 icecast 10067 ccuser 23w REG 9,1 51 7602180 /usr/local/centovacast/var/vhosts/demo/var/log/playlist.log.1

error log is reopening but (access.log and playlist.log) continues empty The command "killall -HUP icecast" does nothing

Tested on last master build (Kh15)

[karlheyes]

can you attach an strace to that and send HUP again. ie

strace -tt -ff -o output -p $(pidof icecast) ctrl-C after HUP sent and you try a few access like index.html etc send me the output.xxxx files

I presume the xml is fairly standard 2.x style, no changes over reload.

Another thing you could do, is grab a core dump, gcore $(pidof icecast) so I can inspect the internal log settings in case they have got messed up.

karl

[edinsof]

[root@localhost ~]# strace -tt -ff -o output -p 10067 strace: Process 10067 attached with 5 threads strace: Process 10067 detached strace: Process 10068 detached strace: Process 10069 detached strace: Process 10070 detached strace: Process 8759 detached [root@localhost ~]# killall -HUP icecast [root@localhost ~]# lsof -nPp '10067' | grep log icecast 10067 ccuser 11w REG 9,1 8413753 7602184 /usr/local/centovacast/var/vhosts/demo/var/log/error.log icecast 10067 ccuser 14w REG 9,1 11903 7602178 /usr/local/centovacast/var/vhosts/demo/var/log/access.log icecast 10067 ccuser 23w REG 9,1 51 7602180 /usr/local/centovacast/var/vhosts/demo/var/log/playlist.log.2 [root@localhost ~]#

[karlheyes]

I think you ctrl-C before the HUP from what I see here. strace, then HUP then ctrl-C the strace, allow for a few seconds between HUP and ctrl-C.

karl.

[edinsof]

[root@localhost ~]# strace -tt -ff -o output -p 10067 strace: Process 10067 attached with 5 threads killall -HUP icecast ^Cstrace: Process 10067 detached strace: Process 10068 detached strace: Process 10069 detached strace: Process 10070 detached strace: Process 13248 detached [root@localhost ~]#

Is correct?

[karlheyes]

no, If the strace is running in the foreground like that then the killall you are typing is not actually done until the shell gets back in control. Either doing the killall on a separate terminal/login or put the strace into background do the killall then terminate the strace. The former sounds like it will be easier.

karl.

[edinsof]

1. Command in first terminal (strace -tt -ff -o output -p 10067)
2. Wait 5 seconds
3. Command in second terminal (killall -HUP icecast)
4. Wait 5 seconds 5 Ctrl + C in first terminal

[karlheyes]

Can you let me know what you have for the xml (server.conf), I'm specifially interested in the log settings with regard to this. eg logsize etc. Obviously the names are there already. I'll check the specifics of the strace output now that a reload is showing in that. Did you grab a core file from the process (gcore )?

karl

[edinsof]

server.conf file (i changed passwords and ip on file for upload here)

I will grab core file tomorrow

[karlheyes]

I think I've sorted this now. try the latest master, which is just kh15 and this fix

karl.

[edinsof]

Solved thak you =)

[crmb]

i have the same issue with kh15. I am installing the latest master right now.

[BenHippynet]

I'm still seeing this issue in kh15 too.

[karlheyes]

Can you try with the master tree, it is essentially kh15 with one change. Just want to see if that is the issue. If the issue still persists then let me know.

karl.