Subject: posted payments not remaining in the system
From: Bob Miller <..hidden..>
Date: Mon, 21 Jun 2010 12:48:13 -0700
Hello List;
I am hoping someone with better experience can point me in the right direction here with a problem I having on one of my client's installations. Also, I apologize for sending in html format, but it makes the supporting log entries easier to read.
The problem:
-If a payment is entered, printed and posted, it might not be there next time it is looked for.
-The posted payment is visible immediately after it is posted.
-The problem currently occurs on approximately 10-20% of all posted payments.
-There are printed copies of paid invoices that are no longer marked as paid in the system.
-I was also informed this morning that sometimes entire invoices go missing as well, and apparently that happens in clusters, such that out of ten invoices, 3 or 5 may be missing, but then that doesn't happen again for another 50 or so invoices.
Supporting detail regarding end-user:
-This is not an issue of a re-posted invoice.
-The payment is being entered in the Cash=>receipts section, and as far as I can tell the procedure being used is correct (same as I do on my system, and my system does not have this problem).
Some history:
-this is my client's second year using lsmb. After the first year, it was decided to start with a fresh install. I installed 1.2.21, imported customers and vendors as documented using postgres' COPY function, and set the tax variables on said customers and vendors as per a guiding hand from David some months back. My client then entered all outstanding data from the previous year as the last day of the last fiscal year, then closed the year to start the 2010 year. This all happened at the beginning of May.
-I am using the same postgres installation (8.3) as prior to May, I have the old company database in place so it can be viewed as necessary, and the new company is another table in the existing database.
-Since the new installation, my client says that this problem used to happen "once in a while", such that they were not certain it was not human error. Over the weeks though, it has gotten progressively worse, to the point that it happens daily, and it now happens often enough that we can double check the human factor by having a person enter 20 or so invoice payments with another person watching for data entry mistakes - out of those 20, one will almost certainly exhibit this symptom.
-There is a great deal of speculation as to whether this problem existed in the previous year's installation. There was a great deal of "figuring things out" in the first year, and a number of things were done that had unexpected consequences and had to be undone. Nobody can recall if these exact symptoms were present last year, but there were a number of anomalies that seem to have cleared up since we did the new install. However, given the intermittent nature of this problem and the number of little things that didn't seem to go right last year, nobody is certain if this problem transcends both installations or not.
My investigation:
-I have double checked the input method, as best as I can tell, this is not a human making a mistake, nor a human following incorrect procedure.
-I have spent a considerable amount of time on google and in my mailing list history looking for similar situations, because it seems to me I have read about similar situations, but I cannot seem to come up with anything relevant.
-I have searched the system for the possibility that the payment is somehow being moved to some other account or something. So far, there seems to be no evidence to support that this is happening.
-apache throws the following error, however, I also see this error on another installation (version 1.2.18) that does not exhibit this problem, and I cannot match the times with any other clues I found, so I question its relevance:
[Mon Jun 21 09:29:33 2010] [error] [client 192.168.2.30] Name "Config::Std::Hash::DEMOLISH" used only once: possible typo at /usr/share/perl5/Class/Std.pm line 523., referer: http://ledger.tf/
-I ran an fsck on the drive, it did find some errors. However, they were few, and it was possible to recreate the issue within an hour of running the fsck.
-There are no apparent errors in dmesg or syslog indicating any hardware failures or issues.
-The syslog has "out of memory" errors, however, they are all from about 2 weeks before I installed the 1.2.21 version. The box has 2 GB of memory, and runs a number of other web-accessible services that are not experiencing problems (ledgersmb is the only application using postgres - the rest are using mysql). Since I have started this investigation, I have never seen less than 300 MB of free memory, and the vast majority of used memory is buffers.
-Thorough examination of all logs has revealed no other problems on the machine that could have relevance to this issue (for example, there are my failed log in attempts in auth.log that would not apply to this problem).
-Postgres itself has several entries in the logs that look like they are being rolled back. I do not find these types of entries in the version 1.2.18 installation that I am using to compare, and it seems to me that a rollback would fit the description of an entry showing up immediately after it is entered, but disappearing later on.
-That said, a typical rolled-back log entry will happen in one or two seconds, so I am not sure that leaves enough time for a payment entry to be made and verified by a user before the rollback occurs. I have not yet figured out how to correlate these rollbacks in the logs with activity in the web interface to work out if the timing fits the situation.
-I have spent a number of hours trying to deduce if these rollback log entries are the actual problem, or at least additional symptoms of an underlying problem, as there is no error message or failure message to indicate there is a problem within postgres itself. But I find nothing else to go on so far.
-To this end, I have increased logging in postgres to debug1, and about 20 payments were entered since, but the rollback mentioned in the logs below have not showed up so far.
-I was tailing logs this morning and here is a snippet of what I mean about the rollback:
2010-06-21 09:51:33 PDT LOG: execute dbdpg_p16594_1: SELECT u.username, uc.password, uc.crypted_password
FROM users as u, users_conf as uc
WHERE u.username = $1
AND u.id = uc.id;
2010-06-21 09:51:33 PDT DETAIL: parameters: $1 = 'terrafirma'
2010-06-21 09:51:33 PDT LOG: statement: DEALLOCATE dbdpg_p16594_1
2010-06-21 09:51:33 PDT LOG: execute dbdpg_p16594_2: DELETE
FROM session
WHERE session.users_id = (select id from users where username = $1)
AND age(last_used) > $2::interval
2010-06-21 09:51:33 PDT DETAIL: parameters: $1 = 'terrafirma', $2 = '24:00:00'
2010-06-21 09:51:33 PDT LOG: statement: SELECT nextval('session_session_id_seq'), md5(random()::text);
2010-06-21 09:51:33 PDT LOG: execute dbdpg_p16594_3: INSERT INTO session (session_id, users_id, token, transaction_id)
VALUES($1, (SELECT id
FROM users
WHERE username = $2), $3, $4);
2010-06-21 09:51:33 PDT DETAIL: parameters: $1 = '1714', $2 = 'terrafirma', $3 = '727039597fd88181e9d0a21d81155c40', $4 = '782515'
2010-06-21 09:51:33 PDT LOG: execute dbdpg_p16594_4: SELECT setseed($1);
2010-06-21 09:51:33 PDT DETAIL: parameters: $1 = '0.1819727943'
2010-06-21 09:51:33 PDT LOG: statement: DEALLOCATE dbdpg_p16594_3
2010-06-21 09:51:33 PDT LOG: statement: DEALLOCATE dbdpg_p16594_4
2010-06-21 09:51:33 PDT LOG: statement: DEALLOCATE dbdpg_p16594_2
2010-06-21 09:51:33 PDT LOG: execute dbdpg_p16594_5: SELECT acs, address, businessnumber,
company, countrycode, currency,
dateformat, dbdriver, dbhost, dbname,
dboptions, dbpasswd, dbport, dbuser,
email, fax, menuwidth, name, numberformat,
password, print, printer, role, sid,
signature, stylesheet, tel, templates,
timeout, vclimit, u.username
FROM users_conf as uc, users as u
WHERE u.username = $1
AND u.id = uc.id;
2010-06-21 09:51:33 PDT DETAIL: parameters: $1 = 'terrafirma'
2010-06-21 09:51:33 PDT LOG: statement: DEALLOCATE dbdpg_p16594_5
2010-06-21 09:51:33 PDT LOG: statement: begin
2010-06-21 09:51:33 PDT LOG: statement: set DateStyle to 'POSTGRES, US'
2010-06-21 09:51:33 PDT LOG: statement: SELECT t.extends,
coalesce (t.table_name, 'custom_' || extends)
|| ':' || f.field_name as field_def
FROM custom_table_catalog t
JOIN custom_field_catalog f USING (table_id)
2010-06-21 09:51:34 PDT LOG: execute dbdpg_p16594_1: SELECT accno, description, link
FROM chart
WHERE link LIKE $1
ORDER BY accno
2010-06-21 09:51:34 PDT DETAIL: parameters: $1 = '%AP%'
2010-06-21 09:51:34 PDT LOG: statement:
SELECT ct.name AS vendor, ct.curr AS currency, ct.id AS vendor_id,
current_date + ct.terms AS duedate,
ct.notes,
ct.curr AS currency
FROM vendor ct
WHERE ct.id = (select vendor_id from ap where 1 = 1 AND vendor_id IS NOT NULL order by id DESC limit 1)
2010-06-21 09:51:34 PDT LOG: statement: commit
2010-06-21 09:51:34 PDT LOG: statement: DEALLOCATE dbdpg_p16594_1
2010-06-21 09:51:34 PDT LOG: statement: begin
2010-06-21 09:51:34 PDT LOG: statement: SELECT current_date
2010-06-21 09:51:34 PDT LOG: statement:
SELECT value FROM defaults
WHERE setting_key = 'curr'
2010-06-21 09:51:34 PDT LOG: statement:
SELECT value::date FROM defaults
WHERE setting_key = 'closedto'
2010-06-21 09:51:34 PDT LOG: statement:
SELECT value FROM defaults
WHERE setting_key = 'revtrans'
2010-06-21 09:51:34 PDT LOG: execute dbdpg_p16594_2: SELECT count(*) FROM vendor WHERE (startdate IS NULL OR startdate <= $1)
AND (enddate IS NULL OR enddate >= $2)
2010-06-21 09:51:34 PDT DETAIL: parameters: $1 = '06-21-2010', $2 = '06-21-2010'
2010-06-21 09:51:34 PDT LOG: statement: DEALLOCATE dbdpg_p16594_2
2010-06-21 09:51:34 PDT LOG: execute dbdpg_p16594_3: SELECT id, name
FROM vendor
WHERE 1=1
UNION
SELECT id,name
FROM vendor
WHERE id = $1
ORDER BY name
2010-06-21 09:51:34 PDT DETAIL: parameters: $1 = '10180'
2010-06-21 09:51:34 PDT LOG: execute dbdpg_p16594_4: SELECT name, id
FROM employee
WHERE login = $1
2010-06-21 09:51:34 PDT DETAIL: parameters: $1 = 'terrafirma'
2010-06-21 09:51:34 PDT LOG: statement: commit
2010-06-21 09:51:34 PDT LOG: statement: begin
2010-06-21 09:51:34 PDT LOG: execute dbdpg_p16594_5: SELECT id, name
FROM employee
WHERE 1 = 1 AND (startdate IS NULL OR startdate <= $1)
AND (enddate IS NULL OR enddate >= $2) AND sales = '1' ORDER BY name
2010-06-21 09:51:34 PDT DETAIL: parameters: $1 = '06-21-2010', $2 = '06-21-2010'
2010-06-21 09:51:34 PDT LOG: statement: commit
2010-06-21 09:51:34 PDT LOG: statement: DEALLOCATE dbdpg_p16594_5
2010-06-21 09:51:34 PDT LOG: statement: begin
2010-06-21 09:51:34 PDT LOG: statement: SELECT id, description
FROM department
WHERE 1 = 1
ORDER BY 2
2010-06-21 09:51:34 PDT LOG: statement:
SELECT extract('YEARS' FROM transdate) FROM acc_trans
GROUP BY extract('YEARS' FROM transdate) ORDER BY 1 DESC
2010-06-21 09:51:34 PDT LOG: statement: commit
2010-06-21 09:51:34 PDT LOG: statement: DEALLOCATE dbdpg_p16594_4
2010-06-21 09:51:34 PDT LOG: statement: begin
2010-06-21 09:51:34 PDT LOG: execute dbdpg_p16594_6: SELECT *
FROM project
WHERE id NOT IN (SELECT id
FROM parts
WHERE project_id > 0) AND (startdate IS NULL OR startdate <= $1)
AND (enddate IS NULL OR enddate >= $2) ORDER BY projectnumber
2010-06-21 09:51:34 PDT DETAIL: parameters: $1 = '06-21-2010', $2 = '06-21-2010'
2010-06-21 09:51:34 PDT LOG: statement: commit
2010-06-21 09:51:34 PDT LOG: statement: DEALLOCATE dbdpg_p16594_3
2010-06-21 09:51:34 PDT LOG: statement: begin
2010-06-21 09:51:34 PDT LOG: statement: SELECT *
FROM language
ORDER BY 2
2010-06-21 09:51:34 PDT LOG: statement: commit
2010-06-21 09:51:34 PDT LOG: statement: begin
2010-06-21 09:51:34 PDT LOG: execute dbdpg_p16594_7:
SELECT c.name AS vendor, c.discount, c.creditlimit,
c.terms, c.email, c.cc, c.bcc, c.taxincluded,
c.address1, c.address2, c.city, c.state,
c.zipcode, c.country, c.curr AS currency,
c.language_code, to_date('06-21-2010', 'mm-dd-yyyy')
+ c.terms AS duedate,
c.notes AS intnotes,
b.discount AS tradediscount,
b.description AS business,
e.name AS employee, e.id AS employee_id
FROM vendor c
LEFT JOIN business b ON (b.id = c.business_id)
LEFT JOIN employee e ON (e.id = c.employee_id)
WHERE c.id = $1
2010-06-21 09:51:34 PDT DETAIL: parameters: $1 = '10180'
2010-06-21 09:51:34 PDT LOG: statement: DEALLOCATE dbdpg_p16594_6
2010-06-21 09:51:34 PDT LOG: execute dbdpg_p16594_8: SELECT name, id
FROM employee
WHERE login = $1
2010-06-21 09:51:34 PDT DETAIL: parameters: $1 = 'terrafirma'
2010-06-21 09:51:34 PDT LOG: statement: commit
2010-06-21 09:51:34 PDT LOG: statement: DEALLOCATE dbdpg_p16594_7
2010-06-21 09:51:34 PDT LOG: statement: begin
2010-06-21 09:51:34 PDT LOG: execute dbdpg_p16594_9:
SELECT SUM(amount - paid)
FROM ap
WHERE vendor_id = $1
2010-06-21 09:51:34 PDT DETAIL: parameters: $1 = '10180'
2010-06-21 09:51:34 PDT LOG: statement: DEALLOCATE dbdpg_p16594_9
2010-06-21 09:51:34 PDT LOG: execute dbdpg_p16594_10:
SELECT o.amount, (SELECT e.sell FROM exchangerate e
WHERE e.curr = o.curr
AND e.transdate = o.transdate)
FROM oe o
WHERE o.vendor_id = $1
AND o.quotation = '0' AND o.closed = '0'
2010-06-21 09:51:34 PDT DETAIL: parameters: $1 = '10180'
2010-06-21 09:51:34 PDT LOG: statement: DEALLOCATE dbdpg_p16594_10
2010-06-21 09:51:34 PDT LOG: statement:
SELECT *
FROM shipto
WHERE trans_id = 10180
2010-06-21 09:51:34 PDT LOG: execute dbdpg_p16594_11:
SELECT c.accno
FROM chart c
JOIN vendortax ct ON (ct.chart_id = c.id)
WHERE ct.vendor_id = $1
2010-06-21 09:51:34 PDT DETAIL: parameters: $1 = '10180'
2010-06-21 09:51:34 PDT LOG: statement: DEALLOCATE dbdpg_p16594_11
2010-06-21 09:51:34 PDT LOG: statement:
SELECT c.accno, c.description, t.rate, t.taxnumber
FROM chart c
JOIN tax t ON (c.id = t.chart_id)
WHERE c.link LIKE '%AP_tax%'
AND (t.validto >= '06-21-2010' OR t.validto IS NULL)
ORDER BY accno, validto
2010-06-21 09:51:34 PDT LOG: execute dbdpg_p16594_12:
SELECT c.accno, c.description, c.link,
c.category,
ac.project_id,
a.department_id
FROM chart c
JOIN acc_trans ac ON (ac.chart_id = c.id)
JOIN ap a ON (a.id = ac.trans_id)
WHERE a.vendor_id = $1
AND a.id = (SELECT max(id)
FROM ap
WHERE vendor_id =
$2)
2010-06-21 09:51:34 PDT DETAIL: parameters: $1 = '10180', $2 = '10180'
2010-06-21 09:51:34 PDT LOG: statement: DEALLOCATE dbdpg_p16594_12
2010-06-21 09:51:34 PDT LOG: execute dbdpg_p16594_13: select description from department where id = $1
2010-06-21 09:51:34 PDT DETAIL: parameters: $1 = '0'
2010-06-21 09:51:34 PDT LOG: statement: commit
2010-06-21 09:51:34 PDT LOG: statement: DEALLOCATE dbdpg_p16594_13
2010-06-21 09:51:34 PDT LOG: statement: begin
2010-06-21 09:51:34 PDT LOG: execute dbdpg_p16594_14: SELECT t.taxnumber, c.description,
t.rate, t.chart_id, t.pass, m.taxmodulename
FROM tax t INNER JOIN chart c ON (t.chart_id = c.id)
INNER JOIN taxmodule m ON (t.taxmodule_id = m.taxmodule_id)
WHERE c.accno = $1 AND
coalesce(validto::timestamp, 'infinity'::timestamp) >= $2
ORDER BY
coalesce(validto::timestamp, 'infinity'::timestamp) ASC
2010-06-21 09:51:34 PDT DETAIL: parameters: $1 = '2310', $2 = 'Mon Jun 21 00:00:00 2010'
2010-06-21 09:51:34 PDT LOG: statement: DEALLOCATE dbdpg_p16594_14
2010-06-21 09:51:34 PDT LOG: statement: DEALLOCATE dbdpg_p16594_8
2010-06-21 09:51:34 PDT LOG: statement: rollback
-If I am to understand all the snippets and clues I have gathered from googling, postgres is not erroring because it is doing as it is supposed to. This would have me think that ledgersmb is instructing postgres to do database calls that postgres later rolls back. But, thinking is not knowing, and that is a hypotheses I am not able to substantiate.
Summary:
-there is an intermittent and unpredictable problem that is getting progressively worse that is causing the program to be unreliable. If anyone has any suggestions as to a course of action to locate the root of the problem, I would very much appreciate it...
Bob Miller 334-7117/660-5315 http://computerisms.ca ..hidden.. Network, Internet, Server, and Open Source Solutions