Some hoppers disappeared during one transaction

[dotnetguy]

Hello.

Our setup:
Kiosk. It sells tokens.
Paylink, 6 hoppers, note recycler, eagle acceptor.

Standard.cfg

Code: Select all

Hopper at 3 Value 100 // 1 EUR
Hopper at 4 Value 50  // 0,50 EUR 
Hopper at 5 Value 50  // Tokens
Hopper at 6 Value 200 // 2 EUR
Hopper at 7 Value 50  // Tokens
Hopper at 8 Value 50  // Tokens

We had an incident where kiosk requested from paylink to pay out 0.5 eur,
but last pay status returned -6 (no hopper).

Algorithm to payout:
1) Read all dispenser blocks.
2) Set inhibit for desired dispensers (money vs tokens).
3) Write all dispenser blocks.
4) Read all dispenser blocks.
5) Check if correct dispensers are enabled/disabled.
6) If check passsed then paylink.Payout(amount);
7) if check fails then it retries (currently forever).

Our log

Code: Select all

11:31:25.711 ************************** TRANSACTION STARTED **************************
11:31:25.727 System snapshot:
11:31:25.742 0.5 EUR: 295 | 1 EUR: 390 | 2 EUR: 343 | 5 EUR: 11 | Cassette & Box: 73200 | token hopper at 5: 121800 | token hopper at 7: 11183 | token hopper at 8: 1516
11:31:25.758 Requested following:
Payment Method:Cash Payment
Tokens: 5
Free Tokens: 0
UnitPrice: 50
Total: 250
11:31:25.774 Receiving payment ...
11:31:35.224 Accepted: 200 | Amount guided to coinbox/cassette: 200
11:32:03.486 Accepted: 100 | Amount guided to coinbox/cassette: 100
11:32:03.611 Enabling dispenser at 1.
11:32:03.643 Enabling dispenser at 6.
11:32:03.652 Enabling dispenser at 3.
11:32:03.668 Enabling dispenser at 4.
11:32:03.699 Disabling dispenser at 5.
11:32:03.699 Disabling dispenser at 7.
11:32:03.715 Disabling dispenser at 8.
11:32:03.730 Checking if dispenser snapshots were correctly sent to paylink.
11:32:03.746 Checking dispenser at 1. Dispenser is enabled. Dispenser has been correctly setup.
11:32:03.762 Checking dispenser at 6. Dispenser is enabled. Dispenser has been correctly setup.
11:32:03.777 Checking dispenser at 3. Dispenser is enabled. Dispenser has been correctly setup.
11:32:03.808 Checking dispenser at 4. Dispenser is enabled. Dispenser has been correctly setup.
11:32:03.808 Checking dispenser at 5. Dispenser is enabled. It should be disabled. Raising rewrite flag.
11:32:03.824 Checking dispenser at 7. Dispenser is disabled. Dispenser has been correctly setup.
11:32:03.840 Checking dispenser at 8. Dispenser is disabled. Dispenser has been correctly setup.
11:32:03.855 Rewrite dispenser snapshots has been requested for (1 | 3 | 4 | 6).
11:32:03.871 Enabling dispenser at 1.
11:32:03.887 Enabling dispenser at 6.
11:32:03.902 Enabling dispenser at 3.
11:32:03.918 Enabling dispenser at 4.
11:32:03.933 Disabling dispenser at 5.
11:32:03.949 Disabling dispenser at 7.
11:32:03.965 Disabling dispenser at 8.
11:32:03.980 Checking if dispenser snapshots were correctly sent to paylink.
11:32:03.996 Checking dispenser at 1. Dispenser is enabled. Dispenser has been correctly setup.
11:32:04.012 Checking dispenser at 6. Dispenser is enabled. Dispenser has been correctly setup.
11:32:04.043 Checking dispenser at 3. Dispenser is disabled. It should be enabled. Raising rewrite flag.
11:32:04.043 Checking dispenser at 4. Dispenser is enabled. Dispenser has been correctly setup.
11:32:04.058 Checking dispenser at 5. Dispenser is disabled. Dispenser has been correctly setup.
11:32:04.074 Checking dispenser at 7. Dispenser is disabled. Dispenser has been correctly setup.
11:32:04.090 Checking dispenser at 8. Dispenser is disabled. Dispenser has been correctly setup.
11:32:04.105 Rewrite dispenser snapshots has been requested for (1 | 3 | 4 | 6).
11:32:04.121 Enabling dispenser at 1.
11:32:04.137 Enabling dispenser at 6.
11:32:04.152 Enabling dispenser at 3.
11:32:04.168 Enabling dispenser at 4.
11:32:04.183 Disabling dispenser at 5.
11:32:04.199 Disabling dispenser at 7.
11:32:04.215 Disabling dispenser at 8.
11:32:04.230 Checking if dispenser snapshots were correctly sent to paylink.
11:32:04.246 Checking dispenser at 1. Dispenser is enabled. Dispenser has been correctly setup.
11:32:04.262 Checking dispenser at 6. Dispenser is enabled. Dispenser has been correctly setup.
11:32:04.277 Checking dispenser at 3. Dispenser is enabled. Dispenser has been correctly setup.
11:32:04.308 Checking dispenser at 4. Dispenser is enabled. Dispenser has been correctly setup.
11:32:04.340 Checking dispenser at 5. Dispenser is disabled. Dispenser has been correctly setup.
11:32:04.340 Checking dispenser at 7. Dispenser is disabled. Dispenser has been correctly setup.
11:32:04.355 Checking dispenser at 8. Dispenser is disabled. Dispenser has been correctly setup.
11:32:04.371 Payout requested for 50
11:32:04.387 Paylink's snapshot:
11:32:04.402 0.5 EUR: 295 | 1 EUR: 390 | 2 EUR: 343 | 5 EUR: 11 | Cassette & Box: 73500 | token hopper at 5: 121800 | token hopper at 7: 11183 | token hopper at 8: 1516
11:32:04.418 Paying out ...
11:32:05.309 Payout finished.
11:32:05.356 LastPayStatus: -6
11:32:05.402 Paylink's snapshot:
11:32:05.434 0.5 EUR: 295 | 1 EUR: 390 | 2 EUR: 343 | 5 EUR: 11 | Cassette & Box: 73500 | token hopper at 5: 121800 | token hopper at 7: 11183 | token hopper at 8: 1516
11:32:05.449 Receiving payment has been finished.
11:32:05.465 Following amount was received - 300. Is required payment received? True.
11:32:05.480 Printing receipt ...
11:32:07.465 Finished printing receipt.
11:32:07.481 Paying out tokens ...
11:32:07.496 Requested to dispense 5 token(s).
11:32:07.512 Disabling dispenser at 1.
11:32:07.527 Disabling dispenser at 6.
11:32:07.543 Disabling dispenser at 3.
11:32:07.559 Disabling dispenser at 4.
11:32:07.575 Enabling dispenser at 5.
11:32:07.590 Enabling dispenser at 7.
11:32:07.606 Enabling dispenser at 8.
11:32:07.622 Checking if dispenser snapshots were correctly sent to paylink.
11:32:07.637 Checking dispenser at 1. Dispenser is disabled. Dispenser has been correctly setup.
11:32:07.653 Checking dispenser at 6. Dispenser is disabled. Dispenser has been correctly setup.
11:32:07.668 Checking dispenser at 3. Dispenser is disabled. Dispenser has been correctly setup.
11:32:07.684 Checking dispenser at 4. Dispenser is disabled. Dispenser has been correctly setup.
11:32:07.700 Checking dispenser at 5. Dispenser is enabled. Dispenser has been correctly setup.
11:32:07.715 Checking dispenser at 7. Dispenser is enabled. Dispenser has been correctly setup.
11:32:07.731 Checking dispenser at 8. Dispenser is enabled. Dispenser has been correctly setup.
11:32:07.747 Dispenser at 5 has been setup to dispense 5 unit(s).
11:32:07.762 Paying out ...
11:32:09.262 Pay out has ended.
11:32:09.262 Dispenser managed to dispense 5 unit(s).
11:32:09.278 Pay out by dispenser at 5 was successful. LastPayStatus is 1.
11:32:09.293 All requested tokens have been dispensed.
11:32:09.325 Finished paying out tokens. Dispensed tokens - 5
11:32:09.340 ERROR Kiosk [] - Client paid 300 and total was 250, but kiosk returned change for 0.
11:32:09.356 Informing client that kiosk could not return correct amount of change.
11:32:11.715 System snapshot:
11:32:11.731 0.5 EUR: 295 | 1 EUR: 390 | 2 EUR: 343 | 5 EUR: 11 | Cassette & Box: 73500 | token hopper at 5: 121805 | token hopper at 7: 11183 | token hopper at 8: 1516

Paylink's log

Code: Select all

11:31:35.390 ccCoin: enables to 0007
11:31:35.437 CCNet: inhibits to ff ff ff
11:31:35.734 CCNet: Enabling Acceptor
11:31:35.749 CCNet: inhibits to ff ff ff
11:31:35.796 CCNet: Status 14
11:31:56.188 422:10
11:32:03.267 ccHopper@7: Selftest OK
11:32:03.282 DP: Lost event 85000060
11:32:03.486 ccCoin: New event 199, Old 198, coin 2 to 2
11:32:03.486 ccCoin: Selftest OK
11:32:03.517 DP: Lost fault 000000e0
11:32:03.517 
11:32:03.533 DP: System closedown received
11:32:03.533 DP:  No more updates
11:32:03.533 
11:32:03.533 DP: Application has gone away
11:32:03.533 ccCoin: Disable
11:32:03.533 DP: ccCoin Status to 4
11:32:03.533 CCNet: Disable
11:32:03.533 DP: CCNet Status to 4
11:32:03.533 
11:32:03.533 Exec: DP task took 12 msec
11:32:03.533 ccCoin: Inhibit all coins
11:32:03.580 CCNet: Disabling acceptor
11:32:03.683 ccHopper@8: Selftest OK
11:32:03.683 DP: Lost event 86000060
11:32:03.793 ccHopper@5: Selftest OK
11:32:03.793 DP: Lost event 84000060
11:32:03.887 CCNet: Disabling acceptor
11:32:03.949 CCNet: Status 19
11:32:04.027 ccHopper@3: Selftest OK
11:32:04.027 DP: Lost event 82000060
11:32:04.308 ccHopper@4: Selftest OK
11:32:04.324 DP: Lost event 83000060
11:32:04.434 ccHopper@6: Selftest OK
11:32:04.434 DP: Lost event 81000060
11:32:04.480 
11:32:04.480 Ver 001.001.012.008-526 Mar 22 2017 17:04:42
11:32:04.480 DP: Application active
11:32:04.480 DP: Interface memory recovery
11:32:04.480 ccCoin: Enable
11:32:04.480 DP: ccCoin Status to 0
11:32:04.480 CCNet: Enable
11:32:04.480 DP: CCNet Status to 0
11:32:04.480 Exec: DP task took 12 msec
11:32:04.480 CCNet: inhibits to ff ff f0
11:32:04.480 DP: Resending Events
11:32:04.512 DP: Event 001f
11:32:04.512 DP: Turn off barcodes
11:32:04.512 DP: Hopper for 500 enabled
11:32:04.512 DP: Hopper for 100 enabled
11:32:04.512 DP: Hopper for 50 inhibited
11:32:04.512 DP: Hopper for 50 inhibited
11:32:04.543 DP: Hopper for 50 inhibited
11:32:04.543 DP: Pay request for 50, (19758466 - 19758416 (1413188413 - 1393429947))
11:32:04.543 ccCoin: Disable
11:32:04.543 DP: ccCoin Status to 4
11:32:04.543 CCNet: Disable
11:32:04.543 DP: CCNet Status to 4
11:32:04.543 Exec: DP task took 67 msec
11:32:04.543 ccCoin: Inhibit all coins
11:32:05.043 DP: 50 left unqueued
11:32:05.074 DP: Cycle End
11:32:05.168 DP:   Payout still owes 50, (19758466 - 19758416)
11:32:05.168 DP: 50 left unqueued
11:32:05.168 DP:   Finished - overall status: -6, paid now 19758416
11:32:05.168 ccCoin: Enable
11:32:05.168 DP: ccCoin Status to 0
11:32:05.168 CCNet: Enable
11:32:05.168 DP: CCNet Status to 0
11:32:05.199 Exec: DP task took 128 msec
11:32:05.199 ccCoin: Enable all coins
11:32:05.199 ccCoin: enables to 0000
11:32:05.215 CCNet: Enabling Acceptor
11:32:05.262 DP: *** DLL has "noticed" pay result!!
11:32:05.262 CCNet: inhibits to ff ff f0
11:32:05.496 
11:32:05.496 DP: System closedown received
11:32:05.496 DP:  No more updates
11:32:05.496 
11:32:05.496 DP: Application has gone away
11:32:05.496 ccCoin: Disable
11:32:05.496 DP: ccCoin Status to 4
11:32:05.496 CCNet: Disable
11:32:05.496 DP: CCNet Status to 4
11:32:05.496 
11:32:05.496 Exec: DP task took 12 msec
11:32:05.496 ccCoin: Inhibit all coins
11:32:07.793 
11:32:07.840 Ver 001.001.012.008-526 Mar 22 2017 17:04:42
11:32:07.840 DP: Application active
11:32:07.840 DP: Interface memory recovery
11:32:07.840 ccCoin: Enable
11:32:07.840 DP: ccCoin Status to 0
11:32:07.840 CCNet: Enable
11:32:07.840 DP: CCNet Status to 0
11:32:07.840 Exec: DP task took 12 msec
11:32:07.840 CCNet: Enabling Acceptor
11:32:07.840 DP: Resending Events
11:32:07.840 DP: Event 001f
11:32:07.840 DP: Turn off barcodes
11:32:07.840 DP: Hopper for 500 inhibited
11:32:07.840 DP: Hopper for 100 inhibited
11:32:07.840 DP: Hopper for 50 enabled
11:32:07.840 DP: Hopper for 50 enabled
11:32:07.871 DP: Hopper for 50 enabled
11:32:07.871 DP: Pay request for 250, (19758666 - 19758416 (1413188613 - 1393429947))
11:32:07.903 ccCoin: Disable
11:32:07.903 DP: ccCoin Status to 4
11:32:07.903 CCNet: Disable
11:32:07.903 DP: CCNet Status to 4
11:32:07.903 Exec: DP task took 75 msec
11:32:07.903 ccCoin: Inhibit all coins
11:32:08.403 DP: Pay 250 (5 @ 50) from SCH2-NOENCRYPT @ 5
11:32:08.449 ccHopper@5: Request to pay 5...
11:32:08.825 DP: 100 paid so far.
11:32:09.121 ccHopper@5: Final payout status... Event Count 49, Coins: Remaining 0; Paid 5; Unpaid 0
11:32:09.121 DP: 250 paid so far.
11:32:09.121 DP: Cycle End, 5 coins @ 50 status: 1
11:32:09.215 DP:   Finished - overall status: 1, paid now 19758666
11:32:09.246 ccCoin: Enable
11:32:09.246 DP: ccCoin Status to 0
11:32:09.246 CCNet: Enable
11:32:09.246 DP: CCNet Status to 0
11:32:09.246 Exec: DP task took 128 msec
11:32:09.246 ccCoin: Enable all coins
11:32:09.246 CCNet: inhibits to ff ff f0
11:32:09.246 ccCoin: enables to 0000
11:32:09.340 
11:32:09.340 DP: System closedown received
11:32:09.340 DP:  No more updates
11:32:09.340 
11:32:09.340 DP: Application has gone away
11:32:09.340 ccCoin: Disable
11:32:09.340 DP: ccCoin Status to 4
11:32:09.340 CCNet: Disable
11:32:09.340 DP: CCNet Status to 4
11:32:09.340 
11:32:09.340 Exec: DP task took 9 msec
11:32:09.465 ccCoin: Inhibit all coins
11:32:56.127 422:11
11:33:00.784 cctalk:       0 < 00
11:33:00.784 cctalk:      63 > 06

I looked at paylink's log and noticed:

Code: Select all

11:32:04.512 DP: Hopper for 500 enabled
11:32:04.512 DP: Hopper for 100 enabled
11:32:04.512 DP: Hopper for 50 inhibited
11:32:04.512 DP: Hopper for 50 inhibited
11:32:04.543 DP: Hopper for 50 inhibited
11:32:04.543 DP: Pay request for 50, (19758466 - 19758416 (1413188413 - 1393429947))
// Here pay out failed because there were no hopper with value of 50.

but during other transactions:

Code: Select all

12:16:44.217 DP: Hopper for 500 enabled
12:16:44.217 DP: Hopper for 200 enabled
12:16:44.217 DP: Hopper for 100 enabled
12:16:44.217 DP: Hopper for 50 enabled
12:16:44.249 DP: Hopper for 50 inhibited
12:16:44.249 DP: Hopper for 50 inhibited
12:16:44.249 DP: Hopper for 50 inhibited
12:16:44.280 DP: Pay request for 1750, (19761466 - 19759716 (1413191413 - 1393429947))
//This payout succeeded

Smells like a bug in AesImhei namespace

ReadDispenserBlock(snapshot) returned a set of snapshots and kiosk agreed that all hoppers based on those snapshots are correctly setup, yet paylink logs doesn't show that hopper 50 and hopper 200 are enabled.

Additionally. Can we suspect physical hopper disconnection?

Lastly. I made a post some time ago called Inhibited dispensers are sometimes used by AESImhei.Payout(). I wonder if this incident is connected to that.

[davebush]

My best guess at present is that the two hoppers are not running.

Is it possible to get several hours of log ending in the observed problem - that way I can check for anything involving the "missing" hoppers.

[dotnetguy]

I'm afraid that we don't have several hours of logs, but I emailed you what we have.

What do you mean by "not running". Can last pay status be "-6 no hopper" when hopper loses power / is disconnected?

Can last pay status be "-6 no hopper" when AESImehi.Payout(amount) is called when hopper hasn't finished previous dispensing operation?

[davebush]

From your emailed log, it appears that all 6 hoppers were running.

Code: Select all

11:32:03.267 ccHopper@7: Selftest OK
11:32:03.683 ccHopper@8: Selftest OK
11:32:03.793 ccHopper@5: Selftest OK
11:32:04.027 ccHopper@3: Selftest OK
11:32:04.308 ccHopper@4: Selftest OK
11:32:04.434 ccHopper@6: Selftest OK

You then updated the inhibit / enable status on 5 of them (Paylink only logs if it changes):

Code: Select all

11:32:04.512 DP: Hopper for 500 enabled
11:32:04.512 DP: Hopper for 100 enabled
11:32:04.512 DP: Hopper for 50 inhibited
11:32:04.512 DP: Hopper for 50 inhibited
11:32:04.543 DP: Hopper for 50 inhibited

The fact that you got status -6 for the Payout implies that all 4 50p hoppers were inhibited at this time (-6 is Paylink reporting it was unable to find a hopper to issue a payout, either because it doesn't exist or it's inhibited)

Shortly after you enabled 3 of the 4 50p hoppers:

Code: Select all

11:32:07.840 DP: Hopper for 50 enabled
11:32:07.840 DP: Hopper for 50 enabled
11:32:07.871 DP: Hopper for 50 enabled

but then you were able to change a 4th from inhibit to enabled:

Code: Select all

12:16:44.217 DP: Hopper for 50 enabled

which implies it was indeed inhibited at 11:32:04

(Interestingly your code logs control of 7 hoppers, one of them at address 1 which shouldn't exist)

[dotnetguy]

The fact that you got status -6 for the Payout implies that all 4 50p hoppers were inhibited at this time (-6 is Paylink reporting it was unable to find a hopper to issue a payout, either because it doesn't exist or it's inhibited)

I understand. It is just weird that when application found that dispensers were not correctly setup then on 2nd retry it confirmed that dispensers are correctly setup, yet paylink logs show that particular hopper changed its state 30 min later on next transaction.

Our code for enabling/disabling dispensers

Code: Select all

private void EnableDispensersAtAddressesAndDisableEverythingElse(int[] addresses)
{
    var snapshot = new DispenserBlock();
    for (int i = 0; paylink.ReadDispenserDetails(i, out snapshot); i++)
    {
        if (addresses.Contains(snapshot.UnitAddress))
        {
            logger.Info($"Enabling dispenser at {snapshot.UnitAddress}.");
            snapshot.Inhibit = DISPENSER_ENABLED;
        }
        else
        {
            logger.Info($"Disabling dispenser at {snapshot.UnitAddress}.");
            snapshot.Inhibit = DISPENSER_DISABLED;
        }

        paylink.WriteDispenserDetails(i, snapshot);
    }

    var needToRewrite = false;

    logger.Info("Checking if dispenser snapshots were correctly sent to paylink.");
    for (int i = 0; paylink.ReadDispenserDetails(i, out snapshot); i++)
    {
        if (addresses.Contains(snapshot.UnitAddress))
        {
            if (snapshot.Inhibit == DISPENSER_DISABLED)
            {
                logger.Info($"Checking dispenser at {snapshot.UnitAddress}. Dispenser is disabled. It should be enabled. Raising rewrite flag.");
                needToRewrite = true;
            }
            else
            {
                logger.Info($"Checking dispenser at {snapshot.UnitAddress}. Dispenser is enabled. Dispenser has been correctly setup.");
            }
        }
        else
        {
            if(snapshot.Inhibit == DISPENSER_ENABLED)
            {
                logger.Info($"Checking dispenser at {snapshot.UnitAddress}. Dispenser is enabled. It should be disabled. Raising rewrite flag.");
                needToRewrite = true;
            }
            else
            {
                logger.Info($"Checking dispenser at {snapshot.UnitAddress}. Dispenser is disabled. Dispenser has been correctly setup.");
            }
        }
    }

    if (needToRewrite)
    {
        logger.Info($"Rewrite dispenser snapshots has been requested for ({GetAddressesAsString(addresses)}).");
        EnableDispensersAtAddressesAndDisableEverythingElse(addresses);
    }
}

(Interestingly your code logs control of 7 hoppers, one of them at address 1 which shouldn't exist)

We have note recycler also. Its dispenser is at address 1. From application's point of view note dispenser and hoppers are all dispenser blocks.

[davebush]

Having stared at this for a while, I've suddenly realised the significance of the fact that you had bothered to write a "repeat until it sticks" function.

I "knew" that this was unnecessary, and have just spotted that in that case you wouldn't have written it!!

I now think that you've identified a race condition in the dispenser inhibit handling with standard hoppers - I'll be check this more carefully over the next few days.

[dotnetguy]

I'm glad that you had heureka moment

Indeed. Those Acceptor/Dispenser writes are not waited, they are pushed as fast as possible.
Paylink is inevitably a shared state.

[davebush]

Hi,

Have you managed to test the updated testing firmware I e-mailed to you?

Dave