Bank notes are sometimes not correctly accepted

[schneider42]

I've enabled more verbose logging. Waiting for a new case..

[schneider42]

Here are the logs of a 10 Euro bill not being accepted:
https://gist.github.com/schneider42/9465a4725a57fc3baa9b

After pressing the button to "Give change" again, it immediately gave 20 coins of change:
https://gist.github.com/schneider42/7d212a4a2e87f0e9d920

Something is going on with the interface to the bill acceptor. @pc-coholic do you have some insight?

[pc-coholic]

Just so I get this right (without having looked at the logs):

• Enter "Give Change"-menu
• Insert 10 Euro bill
• Bill gets refused
• Fnordload exists "Give Change"-menu
• Enter "Give Change"-menu again
• 20 coins are dispensed without having to put in a new bill

Is that correct, @schneider42 ?

[schneider42]

"Bill gets refused":
The bill gets accepted by the bill acceptor (and put onto the stack) but the fnordload software does not detect this.

The rest is as described.

[pc-coholic]

Logfile 1:
Jan 18 03:05:16 fnordload fnordload.note_validator - DEBUG - poll = ['0xf0', '0xcc', '0xe8'] Jan 18 03:05:16 fnordload fnordload.note_validator - DEBUG - _run:107 with self._essp_lock Jan 18 03:05:16 fnordload fnordload.note_validator - WARNING - Timeout while reading a note Jan 18 03:05:16 fnordload fnordload.note_validator - DEBUG - poll = ['0xf0', '0xe8', '0xcc']

0xF0: Everything is OK
0xCC: Stacking in progress
0xE8: Acceptor is disabled at this time (not accepting any new notes)

This is given multiple times, then the timeout happens (as defined in https://github.com/muccc/fnordload/blob/master/fnordload/note_validator.py#L56).

Logfile 2:
Jan 18 03:17:44 fnordload fnordload.note_validator - WARNING - ['0xf0', '0xe8', '0xcc'] Jan 18 03:17:44 fnordload fnordload.note_validator - DEBUG - poll = ['0xf0', ['0xee', 2], '0x2', '0xcc', '0xcc', '0xeb'] Jan 18 03:17:45 fnordload fnordload.note_validator - DEBUG - read_note:73 with self._essp_lock Jan 18 03:17:45 fnordload fnordload.note_validator - DEBUG - _run:107 with self._essp_lock Jan 18 03:17:45 fnordload fnordload.note_validator - INFO - Read note of value: 10.000000 Jan 18 03:17:45 fnordload fnordload.note_validator - DEBUG - poll = ['0xf0', '0xe8']

0xF0: Everything is OK
0xE8: Acceptor is disabled at this time (not accepting any new notes)
0xCC: Stacking in progress

0xF0: Everything is OK
0xEE: Credit Note on Channel 2
0xEB: Note is stacked

So I think what is happening here is, that we just run into the 30 seconds timeout, while we wait for an answer from the bill-validator.

IMHO this can happen because of two reasons:

1. After 30 seconds the bill actually isn't yet stacked. Increase the timeout.
2. The bill is already stacked, but we are sending too many poll-commands to fast. The NV has already stacked the note and answered our poll-request with a 0xEB/0xEE but we haven't seen it yet, as we are still dealing with the masses of 0xCC-notices that were sent before but are not yet processed.

The developer-manual specifies, that a poll has to occur at least every 5 seconds to keep the device alive.

The master will poll each slave at least every 5 seconds. The slave will deem the host to be inactive, if the time between polls is greater than 5 seconds. If the slave does not receive a poll within 5 seconds it should change to its disabled state. The minimum time between polls is specified for individual peripherals. Only one command can be sent in any one poll sequence.

A long, long time ago, increasing the time between the poll-commands caused problems when using the escrow-function (Hold the money but do not stack it yet): If you didn't send a escrow-poll in time, the devices would have already stacked the banknote before you told it to hold it. But as we are not using this functionality, this should pose no problem.

[schneider42]

I think I now have fairly good idea what happening:

1. Start the procedure
2. Wait almost 30 s
3. Insert bill
4. Bill acceptor starts wirking
5. Script aborts because of timeout
6. Bill acceptor finishes

We just need to disable or retrigger the timeout once a bill is inserted.

[schneider42]

With a 5 Euro bill, I see the following:

32476 Feb  2 01:32:09 fnordload fnordload.note_validator - DEBUG - poll = ['0xf0']
32477 Feb  2 01:32:09 fnordload fnordload.note_validator - DEBUG - _run:107 with self._essp_lock
32478 Feb  2 01:32:09 fnordload fnordload.note_validator - DEBUG - poll = ['0xf0', ['0xef', 0], '0x0']

With a 10 Euro bill, this happened:

Jan 18 03:05:13 fnordload fnordload.note_validator - DEBUG - poll = ['0xf0']
Jan 18 03:05:13 fnordload fnordload.note_validator - DEBUG - _run:107 with self._essp_lock
Jan 18 03:05:13 fnordload fnordload.note_validator - DEBUG - poll = ['0xf0', ['0xef', 0], '0x0'

@pc-coholic: Is this a correct way to see that the acceptor started to get a bill?

[schneider42]

Ah, scrap my last comment. The PR just restarts the timeout on any kind of activity. I think this should be fine.

[pc-coholic]

I merged the PR (which was kinda already present on the machine) - but the problem seems to persist...

Needs further debugging....