Hi,
We have a customer who's Paylink enabled device is returning a TITO ticket which is still being validated, back to the user.
The Paylink driver logs shows this
10:28:32.284 ID-003: barcode 155507629628592177 in escrow
10:28:32.468 DP: return note from disabled ID-003
10:28:32.468 ID-003: Disable
I don't seem to be able to find any point in our application where it purposely disables the note reader, nor tells the Paylink to return the ticket from Escrow. In normal operation, then first time after the ticket was accepted that I see an "ID-003: Disable" is when we initiate a payout.
It is my guess that the JCM or Paylink is occasionally not being polled frequently enough and the JCM debiver automatically disables itself and returns the ticket. I say this because if I stick a breakpoint in my code after the ticket insert is reported, then I can cause the following entries in the Paylink log within 715ms
10:14:15.680 DP: return note from disabled ID-003
10:14:15.680 ID-003: Disable
I've checked the Paylink programmers manual but haven't found any reference to any methods I must continually in a timely manner, in order to ensure correct operation.
Any pointers?
Thanks
Paul
JCM Recycler Autmoatically Returning Ticket From Escrow
Moderators: aardvark, davebush, Admin
Re: JCM Recycler Autmoatically Returning Ticket From Escrow
Hi,
Paylink is not supposed to do that. The diagnostic message "DP: return ..." can be triggered from a few places, but only as a result of an API disable or other events.
Can you post longer excerpts of the log around the problem so I can see what else is going on.
Dave
Paylink is not supposed to do that. The diagnostic message "DP: return ..." can be triggered from a few places, but only as a result of an API disable or other events.
Can you post longer excerpts of the log around the problem so I can see what else is going on.
Dave
Aardvark software developer. Please put all communication on the problem through the board for the benefit of others.
Re: JCM Recycler Autmoatically Returning Ticket From Escrow
I have a log from an actual customer machines. I see the same problem 3 times in that log. Here's just one
08:51:35.899 DP: SCH2-NOENCRYPT Hopper S/N 644813, Address 3, Value 1000 at efc updated
08:51:35.931 ccHopper@3: Timeout set to 10
08:51:43.577 ID-003: Clear Disable
08:51:43.577 DP: ID-003 Status to 0
08:51:43.881 ID-003: All OK
08:51:44.185 ID-003: Enable acceptance
08:51:44.397 DP: Event 000120 for Acceptor 0
08:51:45.621 7288 bytes memory free
08:52:00.579 00:02
08:53:00.413 00:03
08:53:31.084 cctalk: 0 < 00
08:53:31.084 cctalk: 3 > 0a
08:53:31.084 cctalk: 15 < 00
08:53:31.084 cctalk: 63 > 03
08:53:31.084 cctalk: Timeout (88) for 217 to ccHopper @ 3
08:53:31.084 ccHopper@3: No response to message
08:53:31.134 ccHopper@3: Re-Identifying hopper
08:53:31.294 ccHopper@3: Hopper count 213 OK
08:53:31.304 DP: SCH2-NOENCRYPT Hopper S/N 644813, Address 3, Value 1000 at efc updated
08:53:31.344 ccHopper@3: Timeout set to 10
08:53:33.578 cctalk: 0 < 00
08:53:33.578 cctalk: 3 > 0a
08:53:33.578 cctalk: 15 < 00
08:53:33.578 cctalk: 63 > 03
08:53:33.578 cctalk: Timeout (88) for 217 to ccHopper @ 3
08:53:33.578 ccHopper@3: No response to message
08:53:33.628 ccHopper@3: Re-Identifying hopper
08:53:33.788 ccHopper@3: Hopper count 213 OK
08:53:33.808 DP: SCH2-NOENCRYPT Hopper S/N 644813, Address 3, Value 1000 at efc updated
08:53:33.838 ccHopper@3: Timeout set to 10
08:53:59.077 DP: ID-003 Status to 20
08:53:59.547 ID-003: barcode 712542229322736464 in escrow
08:54:00.107 DP: return note from disabled ID-003
08:54:00.107 ID-003: Disable
08:54:00.107 DP: ID-003 Status to 24
08:54:00.128 ID-003: Return Note
08:54:00.212 00:04
08:54:01.502 PC: Update Interlock Set. (36 != 35 / 35)
08:54:01.503 PC: Interlock Now Clear. (After 1 tries.)
08:54:01.604 DP: Pay request for 6000, (591600 - 585600 (3995213595 - 3994621995))
08:54:02.109 DP: Pay 6000 (6 @ 1000) from SCH2-NOENCRYPT @ 3
08:54:02.157 ccHopper@3: Request to pay 6...
08:54:02.413 DP: 1000 paid so far.
08:54:02.528 DP: 2000 paid so far.
08:54:02.639 DP: 3000 paid so far.
08:54:02.701 DP: 4000 paid so far.
08:54:02.816 DP: 5000 paid so far.
08:54:02.939 ccHopper@3: Final payout status... Event Count 05, Coins: Remaining 0; Paid 6; Unpaid 0
08:54:02.939 DP: 6000 paid so far.
08:54:02.939 DP: Cycle End, 6 coins @ 1000 status: 1
08:54:02.975 DP: Finished - overall status: 1, paid now 591600
08:54:02.991 Exec: DP task took 66 msec
08:54:08.117 ID-003: Note returned
08:54:08.117 DP: ID-003 Status to 4
08:54:08.117 DP: Event 000108 for Acceptor 0
08:54:08.245 ID-003: Disable acceptance
08:51:35.899 DP: SCH2-NOENCRYPT Hopper S/N 644813, Address 3, Value 1000 at efc updated
08:51:35.931 ccHopper@3: Timeout set to 10
08:51:43.577 ID-003: Clear Disable
08:51:43.577 DP: ID-003 Status to 0
08:51:43.881 ID-003: All OK
08:51:44.185 ID-003: Enable acceptance
08:51:44.397 DP: Event 000120 for Acceptor 0
08:51:45.621 7288 bytes memory free
08:52:00.579 00:02
08:53:00.413 00:03
08:53:31.084 cctalk: 0 < 00
08:53:31.084 cctalk: 3 > 0a
08:53:31.084 cctalk: 15 < 00
08:53:31.084 cctalk: 63 > 03
08:53:31.084 cctalk: Timeout (88) for 217 to ccHopper @ 3
08:53:31.084 ccHopper@3: No response to message
08:53:31.134 ccHopper@3: Re-Identifying hopper
08:53:31.294 ccHopper@3: Hopper count 213 OK
08:53:31.304 DP: SCH2-NOENCRYPT Hopper S/N 644813, Address 3, Value 1000 at efc updated
08:53:31.344 ccHopper@3: Timeout set to 10
08:53:33.578 cctalk: 0 < 00
08:53:33.578 cctalk: 3 > 0a
08:53:33.578 cctalk: 15 < 00
08:53:33.578 cctalk: 63 > 03
08:53:33.578 cctalk: Timeout (88) for 217 to ccHopper @ 3
08:53:33.578 ccHopper@3: No response to message
08:53:33.628 ccHopper@3: Re-Identifying hopper
08:53:33.788 ccHopper@3: Hopper count 213 OK
08:53:33.808 DP: SCH2-NOENCRYPT Hopper S/N 644813, Address 3, Value 1000 at efc updated
08:53:33.838 ccHopper@3: Timeout set to 10
08:53:59.077 DP: ID-003 Status to 20
08:53:59.547 ID-003: barcode 712542229322736464 in escrow
08:54:00.107 DP: return note from disabled ID-003
08:54:00.107 ID-003: Disable
08:54:00.107 DP: ID-003 Status to 24
08:54:00.128 ID-003: Return Note
08:54:00.212 00:04
08:54:01.502 PC: Update Interlock Set. (36 != 35 / 35)
08:54:01.503 PC: Interlock Now Clear. (After 1 tries.)
08:54:01.604 DP: Pay request for 6000, (591600 - 585600 (3995213595 - 3994621995))
08:54:02.109 DP: Pay 6000 (6 @ 1000) from SCH2-NOENCRYPT @ 3
08:54:02.157 ccHopper@3: Request to pay 6...
08:54:02.413 DP: 1000 paid so far.
08:54:02.528 DP: 2000 paid so far.
08:54:02.639 DP: 3000 paid so far.
08:54:02.701 DP: 4000 paid so far.
08:54:02.816 DP: 5000 paid so far.
08:54:02.939 ccHopper@3: Final payout status... Event Count 05, Coins: Remaining 0; Paid 6; Unpaid 0
08:54:02.939 DP: 6000 paid so far.
08:54:02.939 DP: Cycle End, 6 coins @ 1000 status: 1
08:54:02.975 DP: Finished - overall status: 1, paid now 591600
08:54:02.991 Exec: DP task took 66 msec
08:54:08.117 ID-003: Note returned
08:54:08.117 DP: ID-003 Status to 4
08:54:08.117 DP: Event 000108 for Acceptor 0
08:54:08.245 ID-003: Disable acceptance
Re: JCM Recycler Autmoatically Returning Ticket From Escrow
Hi,
OK, I can see what is happening. I guess that your code issues an Escrow stack and a Payout approximately simultaneously, resulting in a race condition.
If Paylink sees the Payout first, it triggers a disable of all acceptors. (In fact it only needs to disable coins - the problem is dropping coins onto a spinning hopper can have interesting results.)
The Payout race condition was reported recently, and fixed in the latest (mostly maintenance) release: http://www.aardvark.eu.com/downloads/so ... -12-11.zip
Regards
Dave
OK, I can see what is happening. I guess that your code issues an Escrow stack and a Payout approximately simultaneously, resulting in a race condition.
If Paylink sees the Payout first, it triggers a disable of all acceptors. (In fact it only needs to disable coins - the problem is dropping coins onto a spinning hopper can have interesting results.)
The Payout race condition was reported recently, and fixed in the latest (mostly maintenance) release: http://www.aardvark.eu.com/downloads/so ... -12-11.zip
Regards
Dave
Aardvark software developer. Please put all communication on the problem through the board for the benefit of others.
Re: JCM Recycler Autmoatically Returning Ticket From Escrow
Thanks. Are Paylink and Genoa the same product?
It seems the exe you provided has updated my Paylink's firmware from Paylink v1.12.7 to Genoa v1.12.11
Paul
It seems the exe you provided has updated my Paylink's firmware from Paylink v1.12.7 to Genoa v1.12.11
Paul
Re: JCM Recycler Autmoatically Returning Ticket From Escrow
Hi,
Yes ....
Paylink (/Milan) is the overall product name. Our internal name for the Paylink metal box was Genoa, so that persists in the file name of the code updater for the metal box. (Paylink.exe is already used for the driver program!)
You will have to run Genoa.....exe once on each PC with a metal box attached. (If you run it after the initial update, it exits without doing anything. If you add the /check parameter it doesn't even appear on the screen if the code matches.)
Regards
Dave
Yes ....
Paylink (/Milan) is the overall product name. Our internal name for the Paylink metal box was Genoa, so that persists in the file name of the code updater for the metal box. (Paylink.exe is already used for the driver program!)
You will have to run Genoa.....exe once on each PC with a metal box attached. (If you run it after the initial update, it exits without doing anything. If you add the /check parameter it doesn't even appear on the screen if the code matches.)
Regards
Dave
Aardvark software developer. Please put all communication on the problem through the board for the benefit of others.
Re: JCM Recycler Autmoatically Returning Ticket From Escrow
I haven't so far been able to reproduce the customer's issue, only that the recycler returns the note from escrow if I have a breakpoint in my code. With the updated firmware, it still does this
15:09:29.884 DP: ID-003 Status to 0
15:09:29.884 ccCoin: Enable all coins
15:09:29.884 ccCoin: enables to 0809
15:09:29.962 ID-003: Enable acceptance
15:09:29.962 DP: Hopper for 2000 enabled
15:09:30.010 DP: Hopper for 1000 enabled
15:09:30.081 DP: Hopper for 1000 enabled
15:09:30.081 DP: Hopper for 500 enabled
15:09:30.081 DP: Hopper for 500 enabled
15:09:30.081 DP: Hopper for 100 enabled
15:09:30.081 DP: Hopper for 10 enabled
15:09:33.648 ID-003: Note in entrance
15:09:33.671 DP: ID-003 Status to 20
15:09:35.831 ID-003: barcode 012040648913462813 in escrow
15:09:37.231 DP: Application Watchdog triggered
15:09:37.231 ccCoin: Disable
15:09:37.231 DP: ccCoin Status to 4
15:09:37.231 DP: return note from disabled ID-003
15:09:37.231 ID-003: Disable
15:09:37.231 DP: ID-003 Status to 24
15:09:37.231 ccCoin: Inhibit all coins
15:09:37.327 ID-003: Return Note
15:09:38.456 ccCoin: Selftest OK
15:09:38.456 DP: Event 0000e0 for Acceptor 0
15:09:38.812 ccHopper@10: Selftest OK
15:09:39.386 ccHopper@3: Selftest OK
15:09:39.642 00:29
15:09:41.483 ID-003: Note returned
15:09:41.483 ID-003: Entrance now clear
15:09:41.483 DP: ID-003 Status to 4
15:09:41.611 ID-003: Disable acceptance
What is the entry "DP: Application Watchdog triggered" telling us? This is the sort of entry I might expect to see if I had to ensure Paylink polling always occurred, but I'm not aware of any such requirement.
We think that when the customer experienced the problem, the TITO ticket took an unusually long amount of time to validate (17 seconds), yet we think the Paylink returned the ticket before the validation was even complete (ie, our app would not have been at the payout stage yet)
15:09:29.884 DP: ID-003 Status to 0
15:09:29.884 ccCoin: Enable all coins
15:09:29.884 ccCoin: enables to 0809
15:09:29.962 ID-003: Enable acceptance
15:09:29.962 DP: Hopper for 2000 enabled
15:09:30.010 DP: Hopper for 1000 enabled
15:09:30.081 DP: Hopper for 1000 enabled
15:09:30.081 DP: Hopper for 500 enabled
15:09:30.081 DP: Hopper for 500 enabled
15:09:30.081 DP: Hopper for 100 enabled
15:09:30.081 DP: Hopper for 10 enabled
15:09:33.648 ID-003: Note in entrance
15:09:33.671 DP: ID-003 Status to 20
15:09:35.831 ID-003: barcode 012040648913462813 in escrow
15:09:37.231 DP: Application Watchdog triggered
15:09:37.231 ccCoin: Disable
15:09:37.231 DP: ccCoin Status to 4
15:09:37.231 DP: return note from disabled ID-003
15:09:37.231 ID-003: Disable
15:09:37.231 DP: ID-003 Status to 24
15:09:37.231 ccCoin: Inhibit all coins
15:09:37.327 ID-003: Return Note
15:09:38.456 ccCoin: Selftest OK
15:09:38.456 DP: Event 0000e0 for Acceptor 0
15:09:38.812 ccHopper@10: Selftest OK
15:09:39.386 ccHopper@3: Selftest OK
15:09:39.642 00:29
15:09:41.483 ID-003: Note returned
15:09:41.483 ID-003: Entrance now clear
15:09:41.483 DP: ID-003 Status to 4
15:09:41.611 ID-003: Disable acceptance
What is the entry "DP: Application Watchdog triggered" telling us? This is the sort of entry I might expect to see if I had to ensure Paylink polling always occurred, but I'm not aware of any such requirement.
We think that when the customer experienced the problem, the TITO ticket took an unusually long amount of time to validate (17 seconds), yet we think the Paylink returned the ticket before the validation was even complete (ie, our app would not have been at the payout stage yet)
Re: JCM Recycler Autmoatically Returning Ticket From Escrow
Hi,
OK, now that is a different reason. The message "Application Watchdog triggered" is due to the fact that you have used the CheckOperation(Sequence, Timeout) call.
This specifically asks Paylink to disable acceptors (and hence return their contents) if "Timeout" milliseconds elapse since the last call. I would guess that you have specified a timeout parameter of 2000 and do not call the CheckOperation() function while validating the ticket.
There is no requirement to call CheckOperation(), the main reason for doing so is specifically to close down the system if your application stops. You might like to consider:
- Not using CheckOperation
- Changing the Timeout to 20000 (i.e. 20 seconds)
- Checking that the ticket is still in Escrow after the validation.
Regards
Dave
OK, now that is a different reason. The message "Application Watchdog triggered" is due to the fact that you have used the CheckOperation(Sequence, Timeout) call.
This specifically asks Paylink to disable acceptors (and hence return their contents) if "Timeout" milliseconds elapse since the last call. I would guess that you have specified a timeout parameter of 2000 and do not call the CheckOperation() function while validating the ticket.
There is no requirement to call CheckOperation(), the main reason for doing so is specifically to close down the system if your application stops. You might like to consider:
- Not using CheckOperation
- Changing the Timeout to 20000 (i.e. 20 seconds)
- Checking that the ticket is still in Escrow after the validation.
Regards
Dave
Aardvark software developer. Please put all communication on the problem through the board for the benefit of others.
Re: JCM Recycler Autmoatically Returning Ticket From Escrow
That's good to find out, now it gives me something to go on. Exactly the type of call I was looking for.
Thanks Dave
Thanks Dave
Re: JCM Recycler Autmoatically Returning Ticket From Escrow
I've looked into this and it seems we call this on a 500ms timer and use a timeout of 1000ms. There does not appear to be anything to disable this timer, nor inhibit it from executing. I have proven that even when I insert a long delay within our TITO validation, the CheckOperation() method is still being called twice a second.
However what I did notice is that we are getting a watchdog timeout, after a payment (£1 TITO Ticket -> £1 Coin) has been made. This is despite my application continuing to call CheckOperation(). For example in the second 11:11:57, CheckPaylinkUsbStatus() was called twice (internally it calls USBDriverStatus and CheckOperation).
<ERROR> $25/02/2020 11:11:56 Started CheckPaylinkUSBStatus
<ERROR> $25/02/2020 11:11:56 Completed CheckPaylinkUSBStatus
<PS> 25/02/2020 11:11:56 Polling paylink 0....
<PS> 25/02/2020 11:11:56 Paylink poll complete 0
PollMachineStatusTimerElapsed
<ERROR> $25/02/2020 11:11:56 Started CheckPaylinkUSBStatus
<ERROR> $25/02/2020 11:11:56 Completed CheckPaylinkUSBStatus
<PS> 25/02/2020 11:11:57 Polling paylink 0....
<PS> 25/02/2020 11:11:57 Paylink poll complete 0
PollMachineStatusTimerElapsed
<PS> 25/02/2020 11:11:57 Polling paylink 0....
<ERROR> $25/02/2020 11:11:57 Started CheckPaylinkUSBStatus
<ERROR> $25/02/2020 11:11:57 Completed CheckPaylinkUSBStatus
<PS> 25/02/2020 11:11:57 Paylink poll complete 0
PollMachineStatusTimerElapsed
<ERROR> $25/02/2020 11:11:58 Started CheckPaylinkUSBStatus
In that same period the Paylink log shows a timeout. I do note a 21 second delay since the previous entry through (maybe because I inserted a 20s delay in the validation)
11:11:36.176 ID-003: Enable acceptance
11:11:57.801 DP: Application Watchdog triggered
11:11:57.801 ccCoin: Disable
11:11:57.801 DP: ccCoin Status to 4
11:11:57.801 ID-003: Disable
11:11:57.801 DP: ID-003 Status to 4
11:11:57.801 ccCoin: Inhibit all coins
11:11:57.817 ID-003: Disable acceptance
11:11:57.894 DP: Application Watchdog recovered
11:11:57.894 ccCoin: Enable
11:11:57.894 DP: ccCoin Status to 0
11:11:57.894 ID-003: Enable
11:11:57.894 DP: ID-003 Status to 0
11:11:57.894 ccCoin: Enable all coins
11:11:57.894 ccCoin: enables to 080b
11:11:57.974 ID-003: Enable acceptance
I don't suppose there is anyway to have the Paylink log when a watchdog refresh occurred?
I'll post the complete Paylink log sequence here in case it helps.
11:11:01.979 ID-003: Note in entrance
11:11:01.999 DP: ID-003 Status to 20
11:11:04.014 ID-003: barcode 012948648911413965 in escrow
11:11:04.442 ccCoin: Disable
11:11:04.442 DP: ccCoin Status to 4
11:11:04.458 ccCoin: Inhibit all coins
11:11:15.731 01:04
11:11:25.111 DP: Barcode accepted (1/2)
11:11:25.335 ID-003: Stack escrow note to cashbox
11:11:25.703 DP: Hopper for 2000 enabled
11:11:25.763 DP: Hopper for 1000 enabled
11:11:25.763 DP: Hopper for 1000 enabled
11:11:25.763 DP: Hopper for 500 enabled
11:11:25.763 DP: Hopper for 500 enabled
11:11:25.785 DP: Hopper for 100 enabled
11:11:25.785 DP: Hopper for 10 enabled
11:11:25.812 DP: Pay request for 100, (89107540 - 89107440 (3785489866 - 3696382326))
11:11:25.812 ID-003: Disable
11:11:25.812 DP: ID-003 Status to 24
11:11:26.318 DP: Pay 100 (1 @ 100) from SUH1-NOENCRYPT @ 10
11:11:26.367 ccHopper@10: Request to pay 1...
11:11:27.149 ccHopper@10: Final payout status... Event Count 05, Coins: Remaining 0; Paid 1; Unpaid 0
11:11:27.149 DP: 100 paid so far.
11:11:27.149 DP: Cycle End, 1 coins @ 100 status: 1
11:11:27.215 DP: Finished - overall status: 1, paid now 89107540
11:11:27.215 Exec: DP task took 68 msec
11:11:29.851 ID-003: Barcode stacked
11:11:29.851 ID-003: Entrance now clear
11:11:29.851 DP: ID-003 Status to 4
11:11:29.979 ID-003: Disable acceptance
11:11:31.529 PC: Update Interlock Set. (452 != 450 / 450)
11:11:31.530 PC: Interlock Now Clear. (After 1 tries.)
11:11:33.639 ccCoin: Enable
11:11:33.639 DP: ccCoin Status to 0
11:11:33.639 ID-003: Enable
11:11:33.639 DP: ID-003 Status to 0
11:11:33.639 ccCoin: Enable all coins
11:11:33.639 ccCoin: enables to 081f
11:11:33.687 ID-003: Enable acceptance
11:11:34.023 ccCoin: enables to 080b
11:11:34.313 ccCoin: Disable
11:11:34.313 DP: ccCoin Status to 4
11:11:34.313 ID-003: Disable
11:11:34.313 DP: ID-003 Status to 4
11:11:34.313 ccCoin: Inhibit all coins
11:11:34.313 DP: Hopper for 2000 inhibited
11:11:34.313 DP: Hopper for 1000 inhibited
11:11:34.313 DP: Hopper for 1000 inhibited
11:11:34.313 DP: Hopper for 500 inhibited
11:11:34.313 DP: Hopper for 500 inhibited
11:11:34.313 DP: Hopper for 100 inhibited
11:11:34.313 DP: Hopper for 10 inhibited
11:11:34.313 ID-003: Disable acceptance
11:11:35.568 ccCoin: Enable
11:11:35.568 DP: ccCoin Status to 0
11:11:35.568 ID-003: Enable
11:11:35.568 DP: ID-003 Status to 0
11:11:35.568 ccCoin: Enable all coins
11:11:35.568 ID-003: Clear Disable
11:11:35.568 ccCoin: enables to 080b
11:11:35.872 ID-003: All OK
11:11:36.176 ID-003: Enable acceptance
11:11:57.801 DP: Application Watchdog triggered
11:11:57.801 ccCoin: Disable
11:11:57.801 DP: ccCoin Status to 4
11:11:57.801 ID-003: Disable
11:11:57.801 DP: ID-003 Status to 4
11:11:57.801 ccCoin: Inhibit all coins
11:11:57.817 ID-003: Disable acceptance
11:11:57.894 DP: Application Watchdog recovered
11:11:57.894 ccCoin: Enable
11:11:57.894 DP: ccCoin Status to 0
11:11:57.894 ID-003: Enable
11:11:57.894 DP: ID-003 Status to 0
11:11:57.894 ccCoin: Enable all coins
11:11:57.894 ccCoin: enables to 080b
11:11:57.974 ID-003: Enable acceptance
11:12:08.735 DP: Application Watchdog triggered
11:12:08.735 ccCoin: Disable
11:12:08.735 DP: ccCoin Status to 4
11:12:08.735 ID-003: Disable
11:12:08.735 DP: ID-003 Status to 4
11:12:08.752 ccCoin: Inhibit all coins
11:12:08.879 ID-003: Disable acceptance
11:12:15.540 01:05
11:13:15.348 01:06
11:14:15.139 01:07
However what I did notice is that we are getting a watchdog timeout, after a payment (£1 TITO Ticket -> £1 Coin) has been made. This is despite my application continuing to call CheckOperation(). For example in the second 11:11:57, CheckPaylinkUsbStatus() was called twice (internally it calls USBDriverStatus and CheckOperation).
<ERROR> $25/02/2020 11:11:56 Started CheckPaylinkUSBStatus
<ERROR> $25/02/2020 11:11:56 Completed CheckPaylinkUSBStatus
<PS> 25/02/2020 11:11:56 Polling paylink 0....
<PS> 25/02/2020 11:11:56 Paylink poll complete 0
PollMachineStatusTimerElapsed
<ERROR> $25/02/2020 11:11:56 Started CheckPaylinkUSBStatus
<ERROR> $25/02/2020 11:11:56 Completed CheckPaylinkUSBStatus
<PS> 25/02/2020 11:11:57 Polling paylink 0....
<PS> 25/02/2020 11:11:57 Paylink poll complete 0
PollMachineStatusTimerElapsed
<PS> 25/02/2020 11:11:57 Polling paylink 0....
<ERROR> $25/02/2020 11:11:57 Started CheckPaylinkUSBStatus
<ERROR> $25/02/2020 11:11:57 Completed CheckPaylinkUSBStatus
<PS> 25/02/2020 11:11:57 Paylink poll complete 0
PollMachineStatusTimerElapsed
<ERROR> $25/02/2020 11:11:58 Started CheckPaylinkUSBStatus
In that same period the Paylink log shows a timeout. I do note a 21 second delay since the previous entry through (maybe because I inserted a 20s delay in the validation)
11:11:36.176 ID-003: Enable acceptance
11:11:57.801 DP: Application Watchdog triggered
11:11:57.801 ccCoin: Disable
11:11:57.801 DP: ccCoin Status to 4
11:11:57.801 ID-003: Disable
11:11:57.801 DP: ID-003 Status to 4
11:11:57.801 ccCoin: Inhibit all coins
11:11:57.817 ID-003: Disable acceptance
11:11:57.894 DP: Application Watchdog recovered
11:11:57.894 ccCoin: Enable
11:11:57.894 DP: ccCoin Status to 0
11:11:57.894 ID-003: Enable
11:11:57.894 DP: ID-003 Status to 0
11:11:57.894 ccCoin: Enable all coins
11:11:57.894 ccCoin: enables to 080b
11:11:57.974 ID-003: Enable acceptance
I don't suppose there is anyway to have the Paylink log when a watchdog refresh occurred?
I'll post the complete Paylink log sequence here in case it helps.
11:11:01.979 ID-003: Note in entrance
11:11:01.999 DP: ID-003 Status to 20
11:11:04.014 ID-003: barcode 012948648911413965 in escrow
11:11:04.442 ccCoin: Disable
11:11:04.442 DP: ccCoin Status to 4
11:11:04.458 ccCoin: Inhibit all coins
11:11:15.731 01:04
11:11:25.111 DP: Barcode accepted (1/2)
11:11:25.335 ID-003: Stack escrow note to cashbox
11:11:25.703 DP: Hopper for 2000 enabled
11:11:25.763 DP: Hopper for 1000 enabled
11:11:25.763 DP: Hopper for 1000 enabled
11:11:25.763 DP: Hopper for 500 enabled
11:11:25.763 DP: Hopper for 500 enabled
11:11:25.785 DP: Hopper for 100 enabled
11:11:25.785 DP: Hopper for 10 enabled
11:11:25.812 DP: Pay request for 100, (89107540 - 89107440 (3785489866 - 3696382326))
11:11:25.812 ID-003: Disable
11:11:25.812 DP: ID-003 Status to 24
11:11:26.318 DP: Pay 100 (1 @ 100) from SUH1-NOENCRYPT @ 10
11:11:26.367 ccHopper@10: Request to pay 1...
11:11:27.149 ccHopper@10: Final payout status... Event Count 05, Coins: Remaining 0; Paid 1; Unpaid 0
11:11:27.149 DP: 100 paid so far.
11:11:27.149 DP: Cycle End, 1 coins @ 100 status: 1
11:11:27.215 DP: Finished - overall status: 1, paid now 89107540
11:11:27.215 Exec: DP task took 68 msec
11:11:29.851 ID-003: Barcode stacked
11:11:29.851 ID-003: Entrance now clear
11:11:29.851 DP: ID-003 Status to 4
11:11:29.979 ID-003: Disable acceptance
11:11:31.529 PC: Update Interlock Set. (452 != 450 / 450)
11:11:31.530 PC: Interlock Now Clear. (After 1 tries.)
11:11:33.639 ccCoin: Enable
11:11:33.639 DP: ccCoin Status to 0
11:11:33.639 ID-003: Enable
11:11:33.639 DP: ID-003 Status to 0
11:11:33.639 ccCoin: Enable all coins
11:11:33.639 ccCoin: enables to 081f
11:11:33.687 ID-003: Enable acceptance
11:11:34.023 ccCoin: enables to 080b
11:11:34.313 ccCoin: Disable
11:11:34.313 DP: ccCoin Status to 4
11:11:34.313 ID-003: Disable
11:11:34.313 DP: ID-003 Status to 4
11:11:34.313 ccCoin: Inhibit all coins
11:11:34.313 DP: Hopper for 2000 inhibited
11:11:34.313 DP: Hopper for 1000 inhibited
11:11:34.313 DP: Hopper for 1000 inhibited
11:11:34.313 DP: Hopper for 500 inhibited
11:11:34.313 DP: Hopper for 500 inhibited
11:11:34.313 DP: Hopper for 100 inhibited
11:11:34.313 DP: Hopper for 10 inhibited
11:11:34.313 ID-003: Disable acceptance
11:11:35.568 ccCoin: Enable
11:11:35.568 DP: ccCoin Status to 0
11:11:35.568 ID-003: Enable
11:11:35.568 DP: ID-003 Status to 0
11:11:35.568 ccCoin: Enable all coins
11:11:35.568 ID-003: Clear Disable
11:11:35.568 ccCoin: enables to 080b
11:11:35.872 ID-003: All OK
11:11:36.176 ID-003: Enable acceptance
11:11:57.801 DP: Application Watchdog triggered
11:11:57.801 ccCoin: Disable
11:11:57.801 DP: ccCoin Status to 4
11:11:57.801 ID-003: Disable
11:11:57.801 DP: ID-003 Status to 4
11:11:57.801 ccCoin: Inhibit all coins
11:11:57.817 ID-003: Disable acceptance
11:11:57.894 DP: Application Watchdog recovered
11:11:57.894 ccCoin: Enable
11:11:57.894 DP: ccCoin Status to 0
11:11:57.894 ID-003: Enable
11:11:57.894 DP: ID-003 Status to 0
11:11:57.894 ccCoin: Enable all coins
11:11:57.894 ccCoin: enables to 080b
11:11:57.974 ID-003: Enable acceptance
11:12:08.735 DP: Application Watchdog triggered
11:12:08.735 ccCoin: Disable
11:12:08.735 DP: ccCoin Status to 4
11:12:08.735 ID-003: Disable
11:12:08.735 DP: ID-003 Status to 4
11:12:08.752 ccCoin: Inhibit all coins
11:12:08.879 ID-003: Disable acceptance
11:12:15.540 01:05
11:13:15.348 01:06
11:14:15.139 01:07
Re: JCM Recycler Autmoatically Returning Ticket From Escrow
Hi,
This version https://d.pr/f/8ZkMe4 should show you refreshing the watchdog, and how far it had got towards a timeout.
Dave
This version https://d.pr/f/8ZkMe4 should show you refreshing the watchdog, and how far it had got towards a timeout.
Dave
Aardvark software developer. Please put all communication on the problem through the board for the benefit of others.
Re: JCM Recycler Autmoatically Returning Ticket From Escrow
Hi Dave,
Thanks for the special version with that extra watchdog info. Since using it I have not been able to capture an instance of the watchdog timing out. I wonder if it not a watchdog issue after all. This is backed up by the being no mention of a watchdog timeout in the original Paylink.log I posted
For our customer, the issue is happening on each ticket inserted. We have tried updating the firmware to the 4.1.12.11 version you posted, in the hope it might be resolved if it was a race condition, but the problem still persists.
What i have noticed is that all instances of the ticket being returned seem to be preceeded by entries such as these
08:53:31.344 ccHopper@3: Timeout set to 10
08:53:33.578 cctalk: 0 < 00
08:53:33.578 cctalk: 3 > 0a
08:53:33.578 cctalk: 15 < 00
08:53:33.578 cctalk: 63 > 03
08:53:33.578 cctalk: Timeout (88) for 217 to ccHopper @ 3
08:53:33.578 ccHopper@3: No response to message
08:53:33.628 ccHopper@3: Re-Identifying hopper
08:53:33.788 ccHopper@3: Hopper count 213 OK
08:53:33.808 DP: SCH2-NOENCRYPT Hopper S/N 644813, Address 3, Value 1000 at efc updated
08:53:33.838 ccHopper@3: Timeout set to 10
08:53:59.077 DP: ID-003 Status to 20
08:53:59.547 ID-003: barcode 712542229322736464 in escrow
08:54:00.107 DP: return note from disabled ID-003
08:54:00.107 ID-003: Disable
I have yet determine what may be triggering these messages. Might it be something from my application do you think?
Where do I lookup the status values of 20 and 24 that I often see identified against ID003? If the 20 means the device has been made disabled, is there any further evidence in the log as to why this might be getting disabled?
Also, what does it mean when the log shows what appears to be a timestamp (but is not the current time)?
07:29:23.666 16:27
07:30:23.496 16:28
07:31:23.310 16:29
07:32:23.139 16:30
07:33:22.952 16:31
07:34:22.782 16:32
Thanks for the special version with that extra watchdog info. Since using it I have not been able to capture an instance of the watchdog timing out. I wonder if it not a watchdog issue after all. This is backed up by the being no mention of a watchdog timeout in the original Paylink.log I posted
For our customer, the issue is happening on each ticket inserted. We have tried updating the firmware to the 4.1.12.11 version you posted, in the hope it might be resolved if it was a race condition, but the problem still persists.
What i have noticed is that all instances of the ticket being returned seem to be preceeded by entries such as these
08:53:31.344 ccHopper@3: Timeout set to 10
08:53:33.578 cctalk: 0 < 00
08:53:33.578 cctalk: 3 > 0a
08:53:33.578 cctalk: 15 < 00
08:53:33.578 cctalk: 63 > 03
08:53:33.578 cctalk: Timeout (88) for 217 to ccHopper @ 3
08:53:33.578 ccHopper@3: No response to message
08:53:33.628 ccHopper@3: Re-Identifying hopper
08:53:33.788 ccHopper@3: Hopper count 213 OK
08:53:33.808 DP: SCH2-NOENCRYPT Hopper S/N 644813, Address 3, Value 1000 at efc updated
08:53:33.838 ccHopper@3: Timeout set to 10
08:53:59.077 DP: ID-003 Status to 20
08:53:59.547 ID-003: barcode 712542229322736464 in escrow
08:54:00.107 DP: return note from disabled ID-003
08:54:00.107 ID-003: Disable
I have yet determine what may be triggering these messages. Might it be something from my application do you think?
Where do I lookup the status values of 20 and 24 that I often see identified against ID003? If the 20 means the device has been made disabled, is there any further evidence in the log as to why this might be getting disabled?
Also, what does it mean when the log shows what appears to be a timestamp (but is not the current time)?
07:29:23.666 16:27
07:30:23.496 16:28
07:31:23.310 16:29
07:32:23.139 16:30
07:33:22.952 16:31
07:34:22.782 16:32
Last edited by paulp on Fri Feb 28, 2020 3:51 pm, edited 1 time in total.
Re: JCM Recycler Autmoatically Returning Ticket From Escrow
The sequence at 08:53:33 recurs regularly with all Compact Hoppers. A fault in the firmware means they occasionally miss a poll reply, and Paylink then checks that it wasn't due to a replacement.
I remain convinced that at 08:54:00 your application disabled the acceptor.
1/ Have you got a similar trace that didn't return the ticket (is there any sign of a disable)
2/ Early next week I'll give you a version that specifically logs why an acceptor is disabled.
I remain convinced that at 08:54:00 your application disabled the acceptor.
1/ Have you got a similar trace that didn't return the ticket (is there any sign of a disable)
2/ Early next week I'll give you a version that specifically logs why an acceptor is disabled.
Aardvark software developer. Please put all communication on the problem through the board for the benefit of others.
Re: JCM Recycler Autmoatically Returning Ticket From Escrow
No signs of a disable when it doesn't return the ticket
10:44:28.539 ID-003: Note in entrance
10:44:28.539 DP: ID-003 Status to 20
10:44:30.703 ID-003: barcode 012242608925463914 in escrow
10:44:31.244 ccCoin: Disable
10:44:31.244 DP: ccCoin Status to 4
10:44:31.244 ccCoin: Inhibit all coins
10:44:36.379 DP: Barcode accepted (0/1)
10:44:36.459 ID-003: Stack escrow note to cashbox
10:44:40.905 ID-003: Barcode stacked
10:44:40.905 ID-003: Entrance now clear
10:44:40.923 DP: ID-003 Status to 0
10:44:28.539 ID-003: Note in entrance
10:44:28.539 DP: ID-003 Status to 20
10:44:30.703 ID-003: barcode 012242608925463914 in escrow
10:44:31.244 ccCoin: Disable
10:44:31.244 DP: ccCoin Status to 4
10:44:31.244 ccCoin: Inhibit all coins
10:44:36.379 DP: Barcode accepted (0/1)
10:44:36.459 ID-003: Stack escrow note to cashbox
10:44:40.905 ID-003: Barcode stacked
10:44:40.905 ID-003: Entrance now clear
10:44:40.923 DP: ID-003 Status to 0
Re: JCM Recycler Autmoatically Returning Ticket From Escrow
Yes there is! This:
10:44:31.244 ccCoin: Disable
Is you requesting a disable of the Coin Acceptor !!!
10:44:31.244 ccCoin: Disable
Is you requesting a disable of the Coin Acceptor !!!
Aardvark software developer. Please put all communication on the problem through the board for the benefit of others.