-e: print() on closed filehandle LOG error

Moderator: crythias

Post Reply
leocertuche
Znuny newbie
Posts: 40
Joined: 12 Apr 2010, 22:50
Znuny Version: 2.4.7
Location: Medellin, Colombia
Contact:

-e: print() on closed filehandle LOG error

Post by leocertuche »

Hello there!,

We're facing a problem with OTRS that hopefully you'll help us resolving, here is the description:

We're running OTRS 2.4.5 on a openSUSE 10.3 (i586). It's been working great since last year but today users started to experience the following weird behavior: Clicking on any button the browser asks to download index.pl instead of resolves it. After restarting the server the error stops occuring but after awhile it happens again. Checking apache logs we find the following error:

-e: print() on closed filehandle LOG at /opt/otrs//Kernel/Output/HTML/Layout.pm line 1646.

Googling about it I found the following entries which unfortunately did not gave any help:

http://lists.otrs.org/pipermail/otrs/20 ... 26413.html
http://www.mail-archive.com/otrs@otrs.org/msg23744.html
http://www.otrs-forum.de/viewtopic.php? ... 10&p=10768

Unfortunately I have no idea where to start to look for a solution. Any help is much appreciated.

Thanks in advance,

Leonardo Certuche
www.itconsultores.com.co
Medellín, Colombia
Leonardo Certuche
www.itconsultores.com.co
ferrosti
Znuny superhero
Posts: 723
Joined: 10 Oct 2007, 14:30
Znuny Version: 3.0
Location: Hamburg, Germany

-e: print() on closed filehandle LOG error

Post by ferrosti »

This is just a guess, so don´t blame me for that...
I assume that the program tries to write to the logfile, which has already been closed. Since the program code is correct (it usually works) some other code must have closed the filehandle. Even more weird is that you have a log entry that says your log filehandle has been closed. Ever had a DB entry that said DB is down?
I guess your open file limit is exceeded.

[EDIT]
You can give it a try with 'lsof' and have a look at opened pipes or files in specific.
[/EDIT]

Can you give it a try with this?:
http://www.cs.wisc.edu/condor/condorg/l ... ility.html
openSuSE on ESX
IT-Helpdesk: OTRS 3.0
Customer Service: OTRS 3.0 (upgraded from 2.3)
Customer Service (subsidiary): OTRS 3.0
+additional test and development systems
leocertuche
Znuny newbie
Posts: 40
Joined: 12 Apr 2010, 22:50
Znuny Version: 2.4.7
Location: Medellin, Colombia
Contact:

-e: print() on closed filehandle LOG error

Post by leocertuche »

Thanks for your answer ferrosti,

I'll give it a try to the procedure you suggested and let you know (though the error stopped occuring)
Leonardo Certuche
www.itconsultores.com.co
leocertuche
Znuny newbie
Posts: 40
Joined: 12 Apr 2010, 22:50
Znuny Version: 2.4.7
Location: Medellin, Colombia
Contact:

Re: -e: print() on closed filehandle LOG error

Post by leocertuche »

Hi,

We were able to workaround it by making the following changes (thanks to Doug Hall for helping us out on this!)

Edit /etc/security/limits.conf

Add the following to the end..

* hard nofile 65536
* soft nofile 65536

Then reboot

Unfortunately this workaround didn't solve the root cause of the problem, which arised again a few days ago :(
Leonardo Certuche
www.itconsultores.com.co
ferrosti
Znuny superhero
Posts: 723
Joined: 10 Oct 2007, 14:30
Znuny Version: 3.0
Location: Hamburg, Germany

Re: -e: print() on closed filehandle LOG error

Post by ferrosti »

Are you running this instance on a virtual machine?
openSuSE on ESX
IT-Helpdesk: OTRS 3.0
Customer Service: OTRS 3.0 (upgraded from 2.3)
Customer Service (subsidiary): OTRS 3.0
+additional test and development systems
nokernel
Znuny newbie
Posts: 2
Joined: 25 Jun 2010, 15:30
Znuny Version: 2.4.7

Re: -e: print() on closed filehandle LOG error

Post by nokernel »

Sorry to add stuff in here,


We are having exactly the same issue.

I have upped the limits, but eventually we get the closed filehandle issue.

We are running this in a VM, on a SLES 10 with apache 2.2.13 using prefork worker with the 400 max request per child.

Changing the limits did change the situation, but still the issue is still present. To me that looks like an issue in the code that does not close all the files it opens.
ferrosti
Znuny superhero
Posts: 723
Joined: 10 Oct 2007, 14:30
Znuny Version: 3.0
Location: Hamburg, Germany

Re: -e: print() on closed filehandle LOG error

Post by ferrosti »

Is your DB running inside the VMs virtual disk?
VMWare as well as mySQL recommend to not virtualize the disks for this scenario.

I have mounted the NetApp disk via NFS and this is doing very well.
Backup took up to an hour and a half. Now I am down to 10 minutes (DB is 18GB by now).
Though I must admit that I wrote a *better* OTRS backup program and changed the time window. I do dump and compression in one process. 'Backup.sh' does this in two steps and this drives nuts.
openSuSE on ESX
IT-Helpdesk: OTRS 3.0
Customer Service: OTRS 3.0 (upgraded from 2.3)
Customer Service (subsidiary): OTRS 3.0
+additional test and development systems
nokernel
Znuny newbie
Posts: 2
Joined: 25 Jun 2010, 15:30
Znuny Version: 2.4.7

Re: -e: print() on closed filehandle LOG error

Post by nokernel »

ferrosti wrote:Is your DB running inside the VMs virtual disk?
VMWare as well as mySQL recommend to not virtualize the disks for this scenario.

I have mounted the NetApp disk via NFS and this is doing very well.
Backup took up to an hour and a half. Now I am down to 10 minutes (DB is 18GB by now).
Though I must admit that I wrote a *better* OTRS backup program and changed the time window. I do dump and compression in one process. 'Backup.sh' does this in two steps and this drives nuts.
Yes indeed, this box VM runs vmware on a virtualised disk, the same disk as the otrs files are.

Do you have link to the information from vmware about the recommendations for running mysql?
ferrosti
Znuny superhero
Posts: 723
Joined: 10 Oct 2007, 14:30
Znuny Version: 3.0
Location: Hamburg, Germany

Re: -e: print() on closed filehandle LOG error

Post by ferrosti »

openSuSE on ESX
IT-Helpdesk: OTRS 3.0
Customer Service: OTRS 3.0 (upgraded from 2.3)
Customer Service (subsidiary): OTRS 3.0
+additional test and development systems
leocertuche
Znuny newbie
Posts: 40
Joined: 12 Apr 2010, 22:50
Znuny Version: 2.4.7
Location: Medellin, Colombia
Contact:

Re: -e: print() on closed filehandle LOG error

Post by leocertuche »

Hello,

we're not virtualizing, it's a dual core with 4GB of RAM running database locally, is it too little for 80 agents and 500 customers?

thanks,
Leonardo Certuche
www.itconsultores.com.co
ferrosti
Znuny superhero
Posts: 723
Joined: 10 Oct 2007, 14:30
Znuny Version: 3.0
Location: Hamburg, Germany

Re: -e: print() on closed filehandle LOG error

Post by ferrosti »

The number of customers does not matter. It is the number of concurrent agents as well as the number of tickets in status !='closed'.
The first will take ressources from apache and latter takes ressources for building queue-views.

What if you tail your logfile and grep this error. When grep succeeds do a lsof and print it to a file. Would be great to see how many files were open.
Next thing would be to update to the latest stable perl AND mySQL version.

I assume the error to be somewhere in between perl and mySQL. What I see is that this error occurs more likely the more my tables are fragmented. This is either due to a bad mySQL file descriptor behavior or just implied through a longer runtime of SQL statements.
Therefor I remove otrs´s crontab and wait for mailimports to settle. Then I flush all tables with read lock and do my backups. Afterwards I release all locks, optimize tables and reinstall crontab for otrs. This works fine for a month now.
openSuSE on ESX
IT-Helpdesk: OTRS 3.0
Customer Service: OTRS 3.0 (upgraded from 2.3)
Customer Service (subsidiary): OTRS 3.0
+additional test and development systems
xofer
Znuny newbie
Posts: 2
Joined: 18 Nov 2010, 21:56
Znuny Version: 3.0.2

Re: -e: print() on closed filehandle LOG error

Post by xofer »

Exactly the same issue:

Quite often i get zero bytes from the web server and apache logs:

Code: Select all

-e: print() on closed filehandle LOG at /opt/otrs//Kernel/Output/HTML/Layout.pm line 1526
Otrs 3.0.2 (RPM) on Centos 5.5
Clean install, 0 tickets

Oh - and i doubt that the limit of open files is an issue here:

Code: Select all

cat /proc/sys/fs/file-nr
1020	0	199365
xofer
Znuny newbie
Posts: 2
Joined: 18 Nov 2010, 21:56
Znuny Version: 3.0.2

Re: -e: print() on closed filehandle LOG error

Post by xofer »

Update: this seems to be an issue with mod_perl and OTRS

If i switch mod_perl off i have not received this error. But of course i lose the speed advantage.
tiagotavares
Znuny newbie
Posts: 1
Joined: 30 Nov 2010, 17:33
Znuny Version: 3.0.3

Re: -e: print() on closed filehandle LOG error

Post by tiagotavares »

Try #ulimit -n 65535 and then restart Apache.

Update:

Forget about it. The most strange is that after some minutes this workaround stops to work....
buzzy
Znuny newbie
Posts: 2
Joined: 19 Jan 2011, 13:49
Znuny Version: 2.4.7

Re: -e: print() on closed filehandle LOG error

Post by buzzy »

Same thing here, seems to be very annoying.

Found 2 workarounds so far:
  • (as stated by xofor) disable mod_perl from apache: slower, and only possible if you don't have any other apps on your server using it
  • periodically restarting apache: restarting every 30 min seems ok. crude with occasional "server down errors"
The problems seems to occur a given time after restart of apache. Playing with file handles seems to increase the time to failure, but doesn't solve it. What you can do:
  • set ulimit (see above)
  • use only 1 access / error log in apache (when using virtual hosts)
I also tried setting a low value for MaxRequestsPerChild, but seems to have no influence.

Checked the mod_perl release notes and such, found nothing. But no new version since 2008.

I suspect this error is due to how OTRS uses file handles that somehow breaks it and thus will file a bug. I suppose there are side-conditions that trigger this error, but I wasn't able to identify them. anyone?
buzzy
Znuny newbie
Posts: 2
Joined: 19 Jan 2011, 13:49
Znuny Version: 2.4.7

Re: -e: print() on closed filehandle LOG error

Post by buzzy »

otrs bug 5338 already exists....
ferrosti
Znuny superhero
Posts: 723
Joined: 10 Oct 2007, 14:30
Znuny Version: 3.0
Location: Hamburg, Germany

Re: -e: print() on closed filehandle LOG error

Post by ferrosti »

Can someone try it when using syslog for logging?
ATM I assume this error to come up only in case logging is set to local file, since syslogs buffers should circumvent this.
openSuSE on ESX
IT-Helpdesk: OTRS 3.0
Customer Service: OTRS 3.0 (upgraded from 2.3)
Customer Service (subsidiary): OTRS 3.0
+additional test and development systems
hendra
Znuny newbie
Posts: 2
Joined: 19 Oct 2012, 06:35
Znuny Version: 3.1.11

Re: -e: print() on closed filehandle LOG error

Post by hendra »

ferrosti wrote:Can someone try it when using syslog for logging?
ATM I assume this error to come up only in case logging is set to local file, since syslogs buffers should circumvent this.
Hi,

I'm on 3.1.11 and logging to syslog, but I'm still getting this error. Is there a permanent fix for this already?

Code: Select all

-e: print() on closed filehandle LOG at /opt/otrs//Kernel/Output/HTML/Layout.pm line 1643.
OTRS 3.1 on CentOS with MySQL, connected to an AD for Agents
crythias
Moderator
Posts: 10169
Joined: 04 May 2010, 18:38
Znuny Version: 5.0.x
Location: SouthWest Florida, USA
Contact:

Re: -e: print() on closed filehandle LOG error

Post by crythias »

Searching seems to indicate that the file cannot be opened for writing.
However, more to the point, this error often comes up when there's an issue with another subsystem.

Code: Select all

1643	    print ${ $Param{Output} };
"print" will use the currently assigned global filehandle, which apparently is LOG at the time of this error. The only normal way that should change from htmlout/stdout (this is pseudo code.) to LOG is that something that the Layout print subroutine calls or that calls the Layout print subroutine crashed and while it was logging the error, the logging of the error didn't return to normal output from file LOGging.

On one hand, this might be considered a bug, on the other hand, the result exists because there's another problem that was being LOGged.
OTRS 6.0.x (private/testing/public) on Linux with MySQL database.
Please edit your signature to include your OTRS version, Operating System, and database type.
Click Subscribe Topic below to get notifications. Consider amending your topic title to include [SOLVED] if it is so.
Need help? Before you ask
hendra
Znuny newbie
Posts: 2
Joined: 19 Oct 2012, 06:35
Znuny Version: 3.1.11

Re: -e: print() on closed filehandle LOG error

Post by hendra »

Thanks crythias, any known workaround or temp-fix for this? At the moment I'm using monit to monitor apache log and reload apache whenever there's this error. I'd rather modify the source code to circumvent this if possible. Any advice?

Update:
Went to http://bugs.otrs.org/show_bug.cgi?id=5338 and followed the suggestion to remove mod_perl, currently monitoring this after the change...
OTRS 3.1 on CentOS with MySQL, connected to an AD for Agents
crythias
Moderator
Posts: 10169
Joined: 04 May 2010, 18:38
Znuny Version: 5.0.x
Location: SouthWest Florida, USA
Contact:

Re: -e: print() on closed filehandle LOG error

Post by crythias »

hendra wrote: any known workaround or temp-fix for this?
Yes, find out the thing that is being logged before the error message occurs. It's likely to be rather consistent, and if we know what it is, the act of logging that issue needs to be addressed.
OTRS 6.0.x (private/testing/public) on Linux with MySQL database.
Please edit your signature to include your OTRS version, Operating System, and database type.
Click Subscribe Topic below to get notifications. Consider amending your topic title to include [SOLVED] if it is so.
Need help? Before you ask
crythias
Moderator
Posts: 10169
Joined: 04 May 2010, 18:38
Znuny Version: 5.0.x
Location: SouthWest Florida, USA
Contact:

Re: -e: print() on closed filehandle LOG error

Post by crythias »

hm. LOG comes from Carp.
Carp is only called directly in OTRS via System/Web/Request.pm

Code: Select all

    # send errors to web server error log
    use CGI::Carp;
and this incidentally is called by
Output/HTML/Layout.pm: use Kernel::System::Web::Request;

Well, that's a fine thing. I'm not sure we need
use CGI::Carp
Comment it out and see what breaks?
OTRS 6.0.x (private/testing/public) on Linux with MySQL database.
Please edit your signature to include your OTRS version, Operating System, and database type.
Click Subscribe Topic below to get notifications. Consider amending your topic title to include [SOLVED] if it is so.
Need help? Before you ask
ferrosti
Znuny superhero
Posts: 723
Joined: 10 Oct 2007, 14:30
Znuny Version: 3.0
Location: Hamburg, Germany

Re: -e: print() on closed filehandle LOG error

Post by ferrosti »

Is anyone experiencing this in non Virtual Machines?
AFAIR there had been a bug in either ESXi or one of its components regarding the virtual IO.

Another matter was perl itself when run with mod_perl. Some perl module was written in a not thread-safe manner.
openSuSE on ESX
IT-Helpdesk: OTRS 3.0
Customer Service: OTRS 3.0 (upgraded from 2.3)
Customer Service (subsidiary): OTRS 3.0
+additional test and development systems
crythias
Moderator
Posts: 10169
Joined: 04 May 2010, 18:38
Znuny Version: 5.0.x
Location: SouthWest Florida, USA
Contact:

Re: -e: print() on closed filehandle LOG error

Post by crythias »

ferrosti, can you try my previous post? See if commenting out CARP works?
OTRS 6.0.x (private/testing/public) on Linux with MySQL database.
Please edit your signature to include your OTRS version, Operating System, and database type.
Click Subscribe Topic below to get notifications. Consider amending your topic title to include [SOLVED] if it is so.
Need help? Before you ask
ferrosti
Znuny superhero
Posts: 723
Joined: 10 Oct 2007, 14:30
Znuny Version: 3.0
Location: Hamburg, Germany

Re: -e: print() on closed filehandle LOG error

Post by ferrosti »

Hi crythias,
I have not experienced this error for more than ten months now. It could possibly have to do with an upgrade of our ESXi machines. That´s why I were asking.

Regards,
Chris
openSuSE on ESX
IT-Helpdesk: OTRS 3.0
Customer Service: OTRS 3.0 (upgraded from 2.3)
Customer Service (subsidiary): OTRS 3.0
+additional test and development systems
RIAIngo
Znuny newbie
Posts: 77
Joined: 26 Nov 2012, 18:18
Znuny Version: 6.0.9
Real Name: Ingo

Re: -e: print() on closed filehandle LOG error

Post by RIAIngo »

I've got the same error on a "normal" Hardware
ferrosti
Znuny superhero
Posts: 723
Joined: 10 Oct 2007, 14:30
Znuny Version: 3.0
Location: Hamburg, Germany

Re: -e: print() on closed filehandle LOG error

Post by ferrosti »

Are you running a perl version <= 5.10?
Try whether upgrading perl helps.
openSuSE on ESX
IT-Helpdesk: OTRS 3.0
Customer Service: OTRS 3.0 (upgraded from 2.3)
Customer Service (subsidiary): OTRS 3.0
+additional test and development systems
tiiibs
Znuny newbie
Posts: 1
Joined: 09 Jul 2013, 12:34
Znuny Version: 3.2.7
Real Name: Mohamed Taieb Riahi
Company: TOPNET

Re: -e: print() on closed filehandle LOG error

Post by tiiibs »

I'm having the same problem with this config :

UBUNTU 12.04 LTS. uname -a result : Linux ubuntu 3.2.0-45-generic #70-Ubuntu SMP Wed May 29 20:12:06 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

APACHE2 Version: 2.2.22-1ubuntu1.3

libapache2-mod_perl2 version : Version: 2.0.5-5ubuntu1

OTRS version : otrs-3.2.7
Post Reply