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
[email protected]
Network, Internet, Server,
and Open Source Solutions
------------------------------------------------------------------------------
ThinkGeek and WIRED's GeekDad team up for the Ultimate
GeekDad Father's Day Giveaway. ONE MASSIVE PRIZE to the
lucky parental unit. See the prize list and enter to win:
http://p.sf.net/sfu/thinkgeek-promo
_______________________________________________
Ledger-smb-users mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/ledger-smb-users
