Kettle gets "Failed to process: Invalid argument 'archetypeId'" errors
For some time I have been getting "Failed to process: Invalid argument 'archetypeId'" errors from the OpenVPMS Loader running in Kettle. I have been ignoring these since they were low frequency and did not appear to be causing any problems.
However, I have just been running comparisions of the debtors balance reports from the RxWorks system I am converting and OpenVPMS. This showed up 3 cases of invoices being lost during the conversion, and this frequency appears to match errors in the log.
Notes:
1. The full set of error messages is:
2013/02/01 17:36:48 - appointment.0 - Failed to process: Invalid argument 'archetypeId'
2013/02/01 17:39:01 - appointment.0 - Processed 39117 rows in 292.8 seconds ( 133.5 rows/sec), generating 244341 objects (834.3 objects/sec)
2013/02/01 17:44:35 - patient-rem.0 - Failed to process: Invalid argument 'archetypeId'
2013/02/01 17:45:05 - patient-rem.0 - Processed 6519 rows in 66.7 seconds ( 97.7 rows/sec), generating 34894 objects (523.4 objects/sec)
2013/02/01 18:31:43 - Tx-invoice.0 - Failed to process: Invalid argument 'archetypeId'
2013/02/01 18:39:32 - Tx-invoice.0 - Processed 68284 rows in 484.6 seconds ( 140.9 rows/sec), generating 341420 objects (704.5 objects/sec)
2013/02/01 21:24:22 - TI-invoice.0 - Failed to process: Invalid argument 'archetypeId'
2013/02/01 21:26:06 - TI-invoice.0 - Processed 201635 rows in 1572.6 seconds ( 128.2 rows/sec), generating 1008168 objects (641.0 objects/sec)
2013/02/01 22:25:44 - PatientMedication.0 - Failed to process: Invalid argument 'archetypeId'
2013/02/01 22:31:13 - PatientMedication.0 - Processed 174499 rows in 430.6 seconds ( 405.2 rows/sec), generating 174499 objects (405.2 objects/sec)
2. As can be seen from the above, the error rate is low, and occurs in various transforms (I use 103 in the conversion which takes some 6 hours to complete).
3. There is insufficient information in the error message to allow me to confirm that the lost invoices are associated with these "invalid argument" messages.
4. I have previously reported a similar message generated by genbalance (see http://www.openvpms.org/forum/16b3-genbalance-error)
Does anyone have any ideas as to what I should do to remedy this problem?
Regards, Tim
![Syndicate content](/misc/feed.png "Comments for \"Kettle gets "Failed to process: Invalid argument 'archetypeId'" errors\""){kind=small}
Re: Kettle gets "Failed to process: Invalid argument ...
Did you see my comment on the linked page?
If that doesn't help, you'll need to enable logging in the spoon.bat script.
To do this, the simplest thing to do would be to:
-Dlog4j.configuration=file:./log4j.propertiesE.g.:
This will log the complete stack trace to openvpms-full.log when you restart spoon.bat
-Tim A
Re: Kettle gets "Failed to process: Invalid argument ...
Tim A:
a) ran the conversion again last night changing nothing except the Spoon Xmx parameter from 2040m to 3096m. There were more Invalid argument errors in different places. (8 this time.)
HOWEVER I still have the same 'RxWorks balances not all same as OpenVPMS balances because lost 3 invoices in conversion' problem, so I suspect that this problem is unrelated to the 'Invalid argument' problem. Indeed further analysis has shown that the balance mismatches are all due to corruptions in the RxWork database. However, I would still like to get to the bottom of the 'Invalid argument' problem.
b) I ran SQL queries looking for arch_short_name is null on the participations, acts and entities tables - none found in all three cases. Note that I "fixed" the genbalance problem (it was only happing on the counter sales/OTC account) by discarding counter sales prior to 1/1/2011 - which significantly reduced the number of transactions in the OTC account.
c) I will turn on logging as you suggest and re-run.
Regards, Tim G
Re: Kettle gets "Failed to process: Invalid argument ...
Did you check the participations.act_arch_short_name column as well?
Re: Kettle gets "Failed to process: Invalid argument ...
Tim A:
1) I have just checked participations for act_arch_short_name being null - none - in fact here are the 4 queries and their results:
select * from participations where arch_short_name is null LIMIT 0, 1000 0 row(s) returned
select * from acts where arch_short_name is null LIMIT 0, 1000 0 row(s) returned
select * from entities where arch_short_name is null LIMIT 0, 1000 0 row(s) returned
select * from participations where act_arch_short_name is null LIMIT 0, 1000 0 row(s) returned
2) The latest conversion run with log4j enabled has completed - still getting the errors, but nothing in the log. The logs (in c:\kettle) were created when I ran spoon.bat - but there is nothing in them. I have had a look at the properties file and the line:
log4j.logger.org.quartz.plugins.history.LoggingJobHistoryPlugin, INFO, stdout, fileout, fullout
worries me - looking at the other entries, I would have thought it should be:
log4j.logger.org.quartz.plugins.history.LoggingJobHistoryPlugin=INFO, stdout, fileout, fullout
Note also, that if this is not the line for the OpenVPMS Loader kettle plugin, then although I can see
log4j.logger.org.openvpms.archetype.tools.account.AccountBalanceTool=INFO, stdout, fileout, fullout
which I suspect is the line for the genbalance utility, I cannot see a line that pertains to the Kettle loader - I would expect something along the lines of:
log4j.logger.org.openvpms.etl.kettle.LoaderPlugin=DEBUG, stdout, fileout, fullout
Are we missing a line like this to tell the OpenVPMS Loader that it should dump debug data to the log file?
Regards, Tim G
Re: Kettle gets "Failed to process: Invalid argument ...
It should be logging errors to openvpms-full.log.
To enable debug logging change the rootLogger to:
log4j.rootLogger=DEBUG, stdout, fileout, fullout
This will likely generate too much logging, so try adding:
log4j.logger.org.openvpms.etl.kettle.LoaderPlugin=DEBUG, stdout, fileout, fullout
Also change any instance of:
org.openvpms.web.component.logging.StackSuppressingPatternLayout
to:
org.apache.log4j.PatternLayout
- Tim A
Re: Kettle gets "Failed to process: Invalid argument ...
Tim A - sorry for the delay, had to divert to other stuff. OK - I managed to get logging to work. Scanning the net I came across a note saying that Kettle's internal settings were causing the log4j.properties to be ignored and that the fix was to give it an equivalent log4j.xml that it would find before its own. This did the trick and I have managed to catch the stacktrace of an instance of the error. The log is attached - I wound the level back to WARN - DEBUG was generating a massive amount of junk. Note that the log contains a real error (caused by the Access database containing no patient number '-9999') - don't worry about this.
Note that each error appears twice - I have a suspicion that this is caused by having both a rootLogger specified as well as the LoaderPlugin specified in the log4j.xml
If you can look at the "Invalid argument 'archetypeId' " stack trace and tell me what to do, I would appreciate it. The line "Failed to save a collection of 1,001 objects." scares me as it implies that I am losing data. However a) all the balances are coming out OK even though these errors are also occuring in the transforms that load the transactions; and b) the stack trace indicates that it is trying to save archetyes and I would have thought that the archetypes themselves were not being updated.
The attached txt file contains both the openvpms-full data and the section of the Kettle log for the transform that was running (Rx_Appointment_100.ktr) and I have also attached the transform itself.
Thanks, Tim G
Re: Kettle gets "Failed to process: Invalid argument ...
The "Failed to save a collection of 1,001 objects" is logged when a batch save fails.
The loader will try and save smaller batches so that all of the rows don't need to be reprocessed.
You should be able to look at the etl_log table at the error_messages column to get more information.
Failing that, try running with a smaller batch size, to see if it logs the problem to etl_log.
-Tim
Re: Kettle gets "Failed to process: Invalid argument ...
Tim A:
a) "select * from etl_log where error_messages is not null;" finds only one record - the one corresponding to the "Failed to retrieve object: <party.patientpet>P-9999" error. ie the "Failed to process: Invalid argument 'archetypeId'" errors do not lead to entries in etl_log. [Somewhat to be expected since we are having problems with the batch save rather than the individual records.]
b) I did some playing with the batch size. Testing with the first transform that gave the error, I dropped the batch size from 1000 to 500 and the error did not occur. Tried 2000 - re-appeared, tried 500 - no error. AHAH - solved - so I set the batch size to to 500 in all transforms, and ran the whole conversion. Arrrgggh - still 3 occurances. I will drop the batch size to 200 and try again.
[Note: if the code were written in something like C I would be looking for a memory overwrite problem. That is, we have something with a low frequency of occurance, that does not seem to be data dependent, and we can effect the behavior by changing buffer/batch sizes. However, I thought Java was immune to that sort of error.]
I will update this in about 7 hours time when the batch=200 run completes.
Re: Kettle gets "Failed to process: Invalid argument ...
I've been able to reproduce this problem. The JIRA is at https://openvpms.atlassian.net/browse/OBF-219
-Tim A