Can't solve this problem of: oversized string, limit is 1048576 bytes
This is a lengthy description but pelase bear with me, I'm really starting to loose hope here...
So I have tried to catch this "oversized string" and avoid it braking my logging but am not able to, even writing debug log failed.
Here is the nxlog.log where you can see that it broke at 5:30, then source log changed and then it broke again and after that it wrote no more to debug nor to syslog anything:
2015-04-17 05:30:45 ERROR procedure 'file_write' failed at line 95, character 100 in C:\Program Files (x86)\nxlog\conf\nxlog.conf. statement execution has been aborted; binary operation failed at line 95, character 99 in C:\Program Files (x86)\nxlog\conf\nxlog.conf. expression evaluation has been aborted; oversized string, limit is 1048576 bytes
2015-04-17 05:30:45 ERROR procedure 'to_syslog_ietf' failed at line 58, character 24 in C:\Program Files (x86)\nxlog\conf\nxlog.conf. statement execution has been aborted; oversized string, limit is 1048576 bytes
2015-04-17 05:30:45 ERROR Syslog_TLS output is over the limit of 65000, will be truncated
2015-04-17 05:31:18 WARNING inode changed for 'C:\Program Files (x86)\Agfa\Sec\Audit\log\audit_9702ad06-126b-4dfd-8b38-ad007eecc9c1.log': reopening possibly rotated file
2015-04-17 05:31:18 ERROR procedure 'file_write' failed at line 95, character 100 in C:\Program Files (x86)\nxlog\conf\nxlog.conf. statement execution has been aborted; binary operation failed at line 95, character 99 in C:\Program Files (x86)\nxlog\conf\nxlog.conf. expression evaluation has been aborted; oversized string, limit is 1048576 bytes
2015-04-17 05:31:18 ERROR procedure 'to_syslog_ietf' failed at line 58, character 24 in C:\Program Files (x86)\nxlog\conf\nxlog.conf. statement execution has been aborted; oversized string, limit is 1048576 bytes
2015-04-17 05:31:18 ERROR Syslog_TLS output is over the limit of 65000, will be truncated
2015-04-17 05:31:18 ERROR procedure 'file_write' failed at line 95, character 100 in C:\Program Files (x86)\nxlog\conf\nxlog.conf. statement execution has been aborted; binary operation failed at line 95, character 99 in C:\Program Files (x86)\nxlog\conf\nxlog.conf. expression evaluation has been aborted; oversized string, limit is 1048576 bytes
2015-04-17 05:31:18 ERROR procedure 'to_syslog_ietf' failed at line 58, character 24 in C:\Program Files (x86)\nxlog\conf\nxlog.conf. statement execution has been aborted; oversized string, limit is 1048576 bytes
2015-04-17 05:31:18 ERROR Syslog_TLS output is over the limit of 65000, will be truncated
2015-04-17 05:31:18 ERROR string limit (1048576 bytes) reached
2015-04-17 05:31:22 ERROR last message repeated 2 times
2015-04-17 05:31:24 ERROR string limit (1048576 bytes) reached
2015-04-17 05:31:26 ERROR string limit (1048576 bytes) reached
2015-04-17 05:31:30 ERROR last message repeated 2 times
2015-04-17 05:31:33 ERROR string limit (1048576 bytes) reached
....and so on just this one message every few second (plus some debug.log rotantion messages) but strangely enough one old log entry from 05:31 popped up later:
2015-04-17 06:00:17 ERROR string limit (1048576 bytes) reached
2015-04-17 05:31:18 ERROR string limit (1048576 bytes) reached
2015-04-17 06:00:21 INFO removing file F:\\temp\debug.log.2
..
and also debug.log failed but this is not the concerne right now:
2015-04-17 07:00:21 ERROR failed to determine file size of 'F:\\temp\debug.log': The system cannot find the file specified.
The last events in debug.log.1 are:
EventTime: , raw_event: !SYS 2015-04-17 05:31:18,754 - apr 08 11:33:31 193.40.48.28 <?xml version="1.0" encoding="UTF-8" ?>
EventTime: , raw_event: <IHEYr4><DicomQuery><Keys></Keys><Requestor><IP></IP></Requestor><CUID></CUID><SyntaxUID>LittleIndianImplicit</SyntaxUID></DicomQuery><Host>193.40.48.28</Host><TimeStamp>2015-04-08T11:33:31+03:00</TimeStamp></IHEYr4>
EventTime: , raw_event: !SYS 2015-04-17 05:31:18,832 - apr 08 11:33:31 193.40.48.28 <?xml version="1.0" encoding="UTF-8" ?>
The last NORMALISED event (the whole configuration depens on dropping the CUID's - there can be up to 20000 CUIDs in one event - and wiritin this instead: <UIDs>dropped by nxlog</UIDs> and taking the TimeStamp from the end of the raw event and making it the real EventTime) in syslog server is:
2015-04-08T11:33:31.000000+03:00 <IHEYr4><DICOMInstancesUsed><ObjectAction>Access</ObjectAction><AccessionNumber>83_13532</AccessionNumber><SUID>1.2.124.113532.192.168.100.131.20050117.92248.281238</SUID><Patient><PatientID>50411232772</PatientID><PatientName>PATIENT^1</PatientName></Patient><User><LocalUser>user1@Agfa Healthcare</LocalUser></User><UIDs>dropped by nxlog</UIDs><NumberOfInstances>91</NumberOfInstances><MPPSUID></MPPSUID></DICOMInstancesUsed><Host>193.40.48.28</Host><TimeStamp>2015-04-08T11:33:31+03:00</TimeStamp></IHEYr4>
So to come back to nxlog.log events in the beginning here is the output to syslog at the moment when nxliog broke at 5:30 and 5:31 (here you can see that some events start normally (without the tag) and with <IHEYr4> in the beginning but as they are here it means that the event time has not been replaced and the CUID's have not been cut out and these events then get broken up to serveral garbaged messages:
@timestamp tag severity host facility message
2015-04-17T05:30:45.776+03:00 debug server1 invld <IHEYr4><DICOMInstancesUsed><Object...
2015-04-17T05:30:45.777+03:00 UID><CUID>1.3.46.670589.11.24125.5.0.576.... notice server1 user UID>1.3.46.670589.11.24125.5.0.576.201404240852...
2015-04-17T05:30:45.777+03:00 531903787</CUID><CUID>1.3.46.670589.11... notice server1 user 08531907795</CUID><CUID>1.3.46.670589....
2015-04-17T05:30:45.777+03:00 589.11.24125.5.0.3364.2014042408530195660</CUID... notice server1 user 70589.11.24125.5.0.3364.2014042408530207668</CU...
2015-04-17T05:30:45.778+03:00 ><CUID>1.3.46.670589.11.24125.5.0.576.201... notice server1 user >1.3.46.670589.11.24125.5.0.576.201404240903450...
2015-04-17T05:30:45.778+03:00 .0.576.2014042409034275361</CUID><CUID>... notice server1 user .2014042409034289370</CUID><CUID>1.3.4...
2015-04-17T05:30:45.778+03:00 D><CUID>1.3.46.670589.11.24125.5.0.576.20... notice server1 user D>1.3.46.670589.11.24125.5.0.576.20140424090340...
2015-04-17T05:30:45.779+03:00 0.576.2014042409034712619</CUID><CUID>... notice server1 user 2014042409034726627</CUID><CUID>1.3.46...
2015-04-17T05:30:45.779+03:00 debug server1 invld <CUID>1.3.46.670589.11.24125.5.0.576.2014042...
2015-04-17T05:31:18.831+03:00 debug server1 invld <IHEYr4><DICOMInstancesUsed><Object...
2015-04-17T05:31:18.832+03:00 D><CUID>1.3.46.670589.11.24125.5.0.576.20... notice server1 user D>1.3.46.670589.11.24125.5.0.576.20140424090340...
2015-04-17T05:31:18.832+03:00 UID><CUID>1.3.46.670589.11.24125.5.0.576.... notice server1 user UID>1.3.46.670589.11.24125.5.0.576.201404240852...
2015-04-17T05:31:18.832+03:00 531903787</CUID><CUID>1.3.46.670589.11... notice server1 user 08531907795</CUID><CUID>1.3.46.670589....
2015-04-17T05:31:18.832+03:00 589.11.24125.5.0.3364.2014042408530195660</CUID... notice server1 user 70589.11.24125.5.0.3364.2014042408530207668</CU...
2015-04-17T05:31:18.833+03:00 .0.576.2014042409034275361</CUID><CUID>... notice server1 user .2014042409034289370</CUID><CUID>1.3.4...
2015-04-17T05:31:18.833+03:00 ><CUID>1.3.46.670589.11.24125.5.0.576.201... notice server1 user >1.3.46.670589.11.24125.5.0.576.201404240903450...
2015-04-17T05:31:18.836+03:00 debug server1 invld <CUID>1.3.46.670589.11.24125.5.0.576.2014042...
2015-04-17T05:31:18.836+03:00 0.576.2014042409034712619</CUID><CUID>... notice server1 user 2014042409034726627</CUID><CUID>1.3.46...
2015-04-17T05:31:18.841+03:00 UID><CUID>1.3.46.670589.11.24125.5.0.576.... notice server1 user UID>1.3.46.670589.11.24125.5.0.576.201404240852...
2015-04-17T05:31:18.841+03:00 debug server1 invld <IHEYr4><DICOMInstancesUsed><Object...
2015-04-17T05:31:18.841+03:00 589.11.24125.5.0.3364.2014042408530195660</CUID... notice server1 user 70589.11.24125.5.0.3364.2014042408530207668</CU...
2015-04-17T05:31:18.841+03:00 531903787</CUID><CUID>1.3.46.670589.11... notice server1 user 08531907795</CUID><CUID>1.3.46.670589....
2015-04-17T05:31:18.842+03:00 debug server1 invld <CUID>1.3.46.670589.11.24125.5.0.576.2014042...
2015-04-17T05:31:18.842+03:00 D><CUID>1.3.46.670589.11.24125.5.0.576.20... notice server1 user D>1.3.46.670589.11.24125.5.0.576.20140424090340...
2015-04-17T05:31:18.842+03:00 .0.576.2014042409034275361</CUID><CUID>... notice server1 user .2014042409034289370</CUID><CUID>1.3.4...
2015-04-17T05:31:18.842+03:00 ><CUID>1.3.46.670589.11.24125.5.0.576.201... notice server1 user >1.3.46.670589.11.24125.5.0.576.201404240903450...
2015-04-17T05:31:18.842+03:00 0.576.2014042409034712619</CUID><CUID>... notice server1 user 2014042409034726627</CUID><CUID>1.3.46...
so... I could live with the broken events scattered around (if I see it I know it broke there) but the main thing is that nxlog stops working - it seems it was able to overcome the problem at 5:30 but at 5:31:18 it stopped sending events from this log (other logs were not affected).
So what should I do to make it not break ot at leas always recover and pick up at next message?
Here are the important bits of my config:
<Extension charconv>
Module xm_charconv
AutodetectCharsets utf-8, euc-jp, utf-16, utf-32, iso8859-1, iso8859-4
</Extension>
<Output sslout>
Module om_ssl
Host 192.168.1.2
Port 10514
Exec to_syslog_ietf();
CAFile %CERTDIR%/cacert.pem
CertFile %CERTDIR%/cert.pem
CertKeyFile %CERTDIR%/key.pem
AllowUntrusted TRUE
OutputType Syslog_TLS
Exec if $Message =~ /DEBUG/ drop();
Exec convert_fields("AUTO", "utf-8");
</Output>
<Extension fileop>
Module xm_fileop
<Schedule>
Every 1 hour
Exec if (file_size('%ROOT3%\debug.log') >= 1M) file_cycle('%ROOT3%\debug.log', 2);
</Schedule>
</Extension>
<Input agfaauditlog>
Module im_file
File 'C:\Program Files (x86)\Agfa\Sec\Audit\log\audit_*.log'
SavePos TRUE
ReadFromLast TRUE
Exec file_write("%ROOT3%\debug.log", "EventTime: " + $EventTime + ", raw_event: " + $raw_event);
Exec if $raw_event =~ /!SYS/ drop();
Exec if $raw_event =~ /\<TimeStamp\>(.+)\</ {$EventTime = parsedate($1);}
Exec if $raw_event =~ /^(.+?)(CUID.+CUID)(.+)/ $raw_event = $1 + 'UIDs>dropped by nxlog</UIDs' + $3;
</Input>
<Route 1>
Path internal, nxlog, mseventlog, agfaauditlog => sslout
</Route>
P.S. and then I get events like this also from the same log, why is that?
| 2015-04-17T05:29:40.406+03:00 | 㰱㌾ㄠ㈰ㄵⴰ㐭〸吱ㄺ㌲㨰㘮〰〰〰⬰㌺〰灳㑴汮⁛乘䱏䝀ㄴ㔰㘠䕶敮瑒散敩癥摔業攽∲〱㔭〴ⴱ㜠〵㨲... | notice | server1 | user | 䅣捥獳楯湎畭扥爾䡐剈䵒ㄱ㔰㐰㠰〲㰯䅣捥獳楯湎畭扥爾㱓啉䐾ㄮ㈮㈵〮ㄮ㔹⸴㜰⸱㌮㐵㈮㈰ㄵ〴〸〹㔲㐸⸶㈳⸱... |
