5
responses

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 䅣捥獳楯湎畭扥爾䡐剈䵒ㄱ㔰㐰㠰〲㰯䅣捥獳楯湎畭扥爾㱓啉䐾ㄮ㈮㈵〮ㄮ㔹⸴㜰⸱㌮㐵㈮㈰ㄵ〴〸〹㔲㐸⸶㈳⸱...
AskedApril 17, 2015 - 10:10am

Comments (5)

  • bigfoot's picture

    It's 2.8.1248. I see that newer version is available, gonna try that but is there a mailing list or something that would notify me on a new version?

  • bigfoot's picture

    Installed the latest version and there is No difference. the processing of te log stopped after the ERROR. here you can see the rotation in every 2 minutes but after the error there is nothing but complaints about the string limit until I manually restarted the service:

    2015-04-20 11:07:51 WARNING inode changed for 'C:\Program Files (x86)\Agfa\Sec\Audit\log\audit_28ccb45f-4222-4c51-b1ce-bc078ec4cd08.log': reopening possibly rotated file
    2015-04-20 11:10:36 WARNING inode changed for 'C:\Program Files (x86)\Agfa\Sec\Audit\log\audit_28ccb45f-4222-4c51-b1ce-bc078ec4cd08.log': reopening possibly rotated file
    2015-04-20 11:12:39 WARNING inode changed for 'C:\Program Files (x86)\Agfa\Sec\Audit\log\audit_28ccb45f-4222-4c51-b1ce-bc078ec4cd08.log': reopening possibly rotated file
    2015-04-20 11:14:06 WARNING inode changed for 'C:\Program Files (x86)\Agfa\Sec\Audit\log\audit_28ccb45f-4222-4c51-b1ce-bc078ec4cd08.log': reopening possibly rotated file
    2015-04-20 11:14:22 ERROR string limit (1048576 bytes) reached
    2015-04-20 11:14:26 ERROR last message repeated 2 times
    2015-04-20 11:14:28 ERROR string limit (1048576 bytes) reached
    ...

    2015-04-20 11:23:30 ERROR string limit (1048576 bytes) reached
    2015-04-20 11:23:34 ERROR last message repeated 2 times
    2015-04-20 11:23:36 ERROR string limit (1048576 bytes) reached
    2015-04-20 11:23:38 ERROR string limit (1048576 bytes) reached
     

    Should I write all this to mailing list?

  • adm's picture
    (NXLog)

    If the latest version does not help, it needs to be further investigated. We offer commercial support for the Community Edition if that's an option for you.

    The Enterprise Edition has a StringLimit directive that could be used to prevent this (as a workaround).

    There are only users on the mailing list. You can post your question there but most likely they won't be able to fix the code for you.

Answers (0)