Hi Backendless,
The Timer issue was gone for one day when I recreated Timer and it run successfully on first night, but now it again does not work correctly:
I’ve recorded loom video, where I who users table, realtime logs and execute timer manually.
App id: F001F3BF-4CCD-B35E-FFD0-23845DEE6000
Loom video: Issue with Automatic Timer ⏰ | Loom
Hello, @Uldis_Borkus
We are looking into your problem, will get back with results soon.
Regards,
Serhiy
Could you add logging at the very top (as the first thing) in your timer logic and check if you get those log messages when the timer runs according to the schedule?
Hi @mark-piller
Thanks for looking into it.
I’ve added logging as first thing:
Will update tomorrow.
Hi Uldis,
Make sure that the SERVER_CODE logger’s logging level includes INFO. If it does not, you will not see any log messages fro the cloud code/logic. To manage the log levels, navigate to Manage > Log Management in the Backendless console.
Regards,
Mark
Good Morning,
Thanks for quick reply, I did miss it though so tonight log level for SERVER CODE remained at WARN.
Here is small video update after tonight.
And i noticed that RT log screen is not visible, so attaching it as picture:
Best Regards,
Uldis
Hello,
Unfortunately, the latest video is not helpful.
Messages with theWARN log level are not included when the app level is set to INFO.
The point of adding a log message at the top of the timer was to check if it gets logged when the timer runs. So the most important question right now is whether that log message is logged or not. If it is not, it might be for the reason that the log level is misconfigured.
Regards,
Mark
@mark-piller Understood.
I’ve updated log level for server code to info, so have to wait for tomorrow.
Regarding log level misconfiguration. Logic initially had no loggers inside, only after noticing that something is off after nightly timer runs, i added them. But hopefully tomorrow brings some clarification.
Good Morning @mark-piller .
There is nothing in rt logs even with Server Code log level set to Info:
Although in log file for the day there are some entries:
2024-09-03 21:10:00,396 | SERVER_CODE | INFO | [238726] Building ServerCode Model for path (/opt/backendless/repo/f001f3bf-4ccd-b35e-ffd0-23845dee6000/files/servercode/CODELESS/Leaderboard/PRODUCTION)
2024-09-03 21:10:00,397 | SERVER_CODE | INFO | [238726] ServerCode Model built in 8ms
2024-09-03 21:10:00,403 | SERVER_CODE | INFO | [238726] [A076FB6F-0055-4C73-B373-21AA9F8641C3] [INVOKE SERVICE] services.Leaderboard.resetBonusTier
2024-09-03 21:10:00,410 | BonusTierNightlyLogs | INFO | ===== Start of nightly resetBonusTier =====
2024-09-03 21:10:00,641 | BonusTierNightlyLogs | INFO | UserList selected for update: (6) Email: , Tier: ,Email: , Tier: ,Email: , Tier: ,Email: , Tier: ,Email: , Tier: ,Email: , Tier: ---END---
2024-09-03 21:10:01,071 | BonusTierNightlyLogs | INFO | UserList after update: (6) Email: , Tier: , newTier: , priceCount: ,Email: , Tier: , newTier: , priceCount: ,Email: , Tier: , newTier: , priceCount: ,Email: , Tier: , newTier: , priceCount: ,Email: , Tier: , newTier: , priceCount: ,Email: , Tier: , newTier: , priceCount: ---END---
2024-09-03 21:10:01,071 | SERVER_CODE | INFO | [238726] Processing finished in 692.454ms
2024-09-03 21:10:00,215 | SERVER_CODE | INFO | [238438] Building ServerCode Model for path (/opt/backendless/repo/f001f3bf-4ccd-b35e-ffd0-23845dee6000/files/servercode/CODELESS/Leaderboard/PRODUCTION)
2024-09-03 21:10:00,217 | SERVER_CODE | INFO | [238438] ServerCode Model built in 7ms
2024-09-03 21:10:00,221 | SERVER_CODE | INFO | [238438] [3636D1CB-0171-433B-9C63-8051D010DB6E] [INVOKE TIMER] NightlyBonusTierReset
2024-09-03 21:10:01,075 | SERVER_CODE | INFO | [238438] Processing finished in 875.253ms
Yet still all users are shown as updated (from updated column date changes), but bonusTier is not updated accordingly (there should be only one user with bronze tier).
Is this helping in any way?
Hi @Uldis_Borkus,
I checked your case and it is not reproduced for me. Please add a “Log a message” block in the timer before starting the service. We need to make sure that the timer starts for you.
Regards,
Bohdan
@Bohdan_Vynarchuk You can see that information in logs in previous message:
This one about service invoke:
2024-09-03 21:10:00,403 | SERVER_CODE | INFO | [238726] [A076FB6F-0055-4C73-B373-21AA9F8641C3] [INVOKE SERVICE] services.Leaderboard.resetBonusTier
and this one about timer invoke:
2024-09-03 21:10:00,221 | SERVER_CODE | INFO | [238438] [3636D1CB-0171-433B-9C63-8051D010DB6E] [INVOKE TIMER] NightlyBonusTierReset
And there is close to 0 expectation that this can be reproduced outside of the app ID i provided,
That’s the reason I am trying to give as much details as possible.
And as previously stated, the method apparently does run, but for some reason it only changes is the updated time for each user, not the bonusTier property when executed by Timer.
And works properly when executed manually…
This is what I see in the timer execution history:
This is what I see in the log files:
09/03/2024 16:10:00 (first line in the image above):2024-09-03 21:10:00,410 | BonusTierNightlyLogs | INFO | ===== Start of nightly resetBonusTier =====
2024-09-03 21:10:00,641 | BonusTierNightlyLogs | INFO | UserList selected for update: (6) Email: , Tier: ,Email: , Tier: ,Email: , Tier: ,Email: , Tier: ,Email: , Tier: ,Email: , Tier: ---END---
2024-09-03 21:10:01,071 | BonusTierNightlyLogs | INFO | UserList after update: (6) Email: , Tier: , newTier: , priceCount: ,Email: , Tier: , newTier: , priceCount: ,Email: , Tier: , newTier: , priceCount: ,Email: , Tier: , newTier: , priceCount: ,Email: , Tier: , newTier: , priceCount: ,Email: , Tier: , newTier: , priceCount: ---END---
2024-09-03 21:10:01,071 | SERVER_CODE | INFO | [238726] Processing finished in 692.454ms
09/02/2024 16:10:00 (third line in the image above):2024-09-02 21:10:00,388 | BonusTierNightlyLogs | INFO | ===== Start of nightly resetBonusTier =====
2024-09-02 21:10:00,585 | BonusTierNightlyLogs | INFO | UserList selected for update: (6) Email: , Tier: ,Email: , Tier: ,Email: , Tier: ,Email: , Tier: ,Email: , Tier: ,Email: , Tier: ---END---
2024-09-02 21:10:00,941 | BonusTierNightlyLogs | INFO | UserList after update: (6) Email: , Tier: , newTier: , priceCount: ,Email: , Tier: , newTier: , priceCount: ,Email: , Tier: , newTier: , priceCount: ,Email: , Tier: , newTier: , priceCount: ,Email: , Tier: , newTier: , priceCount: ,Email: , Tier: , newTier: , priceCount: ---END---
You can see the log files for yourself in the Files section of your Backendless app:
The log messages tell me the timer is executed according to schedule. If the question is why the database is not updated, it is not for the reason that timer doesn’t run - the answer must be in your logic. I recommend adding more logging to see what’s going in the code. You could also create another timer that runs more frequently (for debugging purposes). In that timer, you could modify some other test table (or use log messages).
Regards,
Mark
Yes @mark-piller
Questions seems to be more about why there are different outcomes when executed manually vs invoked by Timer.
This is what bothers me the most, because it would be easy to understand if it wouldn’t be working at all, then something is wrong with my logic.
Hi Uldis,
Unfortunately, we cannot review your logic, it is outside of the Backendless support charter.
Regards,
Mark
Yes @mark-piller
Didn’t expect any other response, then why are there different behavior for exactly the same logic Manually invoked Timer vs Scheduled Timer ?
The answer for that question would be in your Codeless logic.
What I know is that the timer IS invoked according to schedule. Your own logs are the evidence supporting that fact
Sorry for going back and forth but still. Since I don’t know internal workings of Backendless timers, i have no where to start, to understand why it behaves differently?
Question: Should manually invoked timer behave the same as timer that is invoked on scheduled time?
Per my my understanding they should behave the same. But this is not the case.
If your logic is dependent on some external factors, then the outcome may be different. For example, if in one run of the timer you retrieve records with a query and you get zero records, that’s outcome A, but in another run you get several records, that’s outcome B.
I see.
Server Time is in GMT+0 Right?
I was thinking, maybe something related to time when executing timer and my logic calculation, since I am at GMT+3.
That is also visible in log file from server code that it runs around 21:00:10 while in timer history it shows my local time 00:00:10.
Will move timer schedule for 3+ hours further so to exclude this one affecting outcome.
Both execution history and the timer setup UI use/show your local time. The log file shows the server time (GMT-0).
