search

seriousm4x / UpSnap

A simple wake on lan web app written with SvelteKit, Go and PocketBase.
MIT License
2.04k stars 77 forks source link

[BUG] Wake cron not executed #669

Open levelsw opened 1 month ago

levelsw commented 1 month ago

The bug

I have a wake cron scheduled daily (0 22 *), I seem to be having some issues where it doesn't execute it (randomly). It was missed the 8th of July and also Yesterday evening (No log entry for it, so it seems like it's not even trying):

[INFO] 2024/07/08 23:05:14 wake.go:16: Wake triggered for Veeam Server (Integrated NIC) [INFO] 2024/07/09 13:34:59 wake.go:16: Wake triggered for Veeam Server (Integrated NIC) [INFO] 2024/07/09 22:00:00 wake.go:16: Wake triggered for Veeam Server (Integrated NIC) [INFO] 2024/07/11 16:31:25 wake.go:16: Wake triggered for Veeam Server (Integrated NIC)

The OS that UpSnap is running on

Ubuntu 22.04.3 LTS

Version of UpSnap

4.2.11

Your docker-compose.yml content

version: "3"
services:
  upsnap:
    container_name: upsnap
    image: ghcr.io/seriousm4x/upsnap:4
    network_mode: host
    restart: unless-stopped
    volumes:
      - ./data:/app/pb_data
    environment:
      - TZ=Europe/Amsterdam # Set container timezone for cron schedules
    dns:
      - X.X.X.X
      - Y.Y.Y.Y

Reproduction steps

1. Schedule wake cron
2. Wait for it to fail

Additional information

No response

kraizelburg commented 1 month ago

I can confirm this also since updating to upsnap v4, for some reasong container does not trigger wake up command.

levelsw commented 1 month ago

It did fail the day after I created this bug as well. Updated to 4.2.12 as that was available and I was still running 4.2.11. For now it went fine for 2 days, but it could be related to something else, that it starts happening after the container is up for a longer time or that something breaks if something specific happens. I will keep monitoring it and update with my findings

kraizelburg commented 1 month ago

For me it broke after v4, went back to v3 and no issues since then.

levelsw commented 1 month ago

Sadly same issue also with 4.2.12. I scheduled it once at 15.40, went fine. Changed the schedule to 22.00, went fine two times, missed it yesterday evening:

[INFO] 2024/07/12 15:40:00 wake.go:16: Wake triggered for Veeam Server (Integrated NIC) [INFO] 2024/07/12 22:00:00 wake.go:16: Wake triggered for Veeam Server (Integrated NIC) [INFO] 2024/07/13 22:00:00 wake.go:16: Wake triggered for Veeam Server (Integrated NIC)

levelsw commented 1 month ago

Restarted upsnap the 15th, it ran the 15th in the evening. It didn't run yesterday evening the 16th. So issue still persists in the last version. 2024/07/15 13:36:51 Server started at http://0.0.0.0:8090 ├─ REST API: http://0.0.0.0:8090/api/ └─ Admin UI: http://0.0.0.0:8090/_/ [INFO] 2024/07/15 22:00:00 wake.go:16: Wake triggered for Veeam Server (Integrated NIC)

I will try V3 as well while waiting for a response to this bug

kraizelburg commented 1 month ago

Restarted upsnap the 15th, it ran the 15th in the evening. It didn't run yesterday evening the 16th. So issue still persists in the last version. 2024/07/15 13:36:51 Server started at http://0.0.0.0:8090 ├─ REST API: http://0.0.0.0:8090/api/ └─ Admin UI: http://0.0.0.0:8090/_/ [INFO] 2024/07/15 22:00:00 wake.go:16: Wake triggered for Veeam Server (Integrated NIC)

I will try V3 as well while waiting for a response to this bug

The issue is persistent since v4 I downgraded to latest v3 and no problems.

seriousm4x commented 1 month ago

I will look into it. I'm not quite sure yet what causes the issue.

levelsw commented 1 month ago

I will look into it. I'm not quite sure yet what causes the issue.

Sure if you want me to test or provide logs or anything just let me know. V3 just works fine

seriousm4x commented 1 month ago

I haven't been able to reproduce the issue yet, so I added some debug logging in the cron wake function so we can see where it stops.

Could you all please try 4.2.13-beta.1 and post the logs here?

levelsw commented 1 month ago

Ok I loaded the beta with this cron (0 1-23 *), so it should now trigger every hour. I will monitor it today

On a sidenote. I wanted it to trigger more than just daily so I tried the cron " /1 " which seemed like it was accepted in the webinterface but it resulted in this error in the console: [ERROR] 2024/08/01 09:25:14 cronjobs.go:149: failed to parse int from : strconv.Atoi: parsing "": invalid syntax

seriousm4x commented 1 month ago

On a sidenote. I wanted it to trigger more than just daily so I tried the cron " /1 " which seemed like it was accepted in the webinterface but it resulted in this error in the console: [ERROR] 2024/08/01 09:25:14 cronjobs.go:149: failed to parse int from : strconv.Atoi: parsing "": invalid syntax

You are missing an asterisk before the slash: * */1 * * *

levelsw commented 1 month ago

On a sidenote. I wanted it to trigger more than just daily so I tried the cron " /1 " which seemed like it was accepted in the webinterface but it resulted in this error in the console: [ERROR] 2024/08/01 09:25:14 cronjobs.go:149: failed to parse int from : strconv.Atoi: parsing "": invalid syntax

You are missing an asterisk before the slash: * */1 * * *

Ouch https://crontab.cronhub.io/ didn't flag this as a formatting issue, thanks!

levelsw commented 1 month ago

FYI: The cron woke up the server a couple times now and it didn't fail yet. I think it is time related (I think it always happened after one occurrence, so after >24 hours. I returned the corn to the original timing (every evening at 22.00) and will check if tonight at 22.00 it runs, and if tomorrow at 22.00 it will run again.

Log output attached as a reference (there's a wrong IP configured so in the logs it says it didn't wake up after 2 mins, which is not true, it just worked each time)


[INFO] 2024/08/01 09:06:28 wake.go:16: Wake triggered for Veeam Server (Integrated NIC)
[ERROR] 2024/08/01 09:25:14 cronjobs.go:149: failed to parse int from : strconv.Atoi: parsing "": invalid syntax
[ERROR] 2024/08/01 09:26:11 cronjobs.go:149: failed to parse int from : strconv.Atoi: parsing "": invalid syntax
[INFO] 2024/08/01 09:48:47 wake.go:16: Wake triggered for Octoprint
[DEBUG] 2024/08/01 10:00:00 cronjobs.go:116: [CRON1 "Veeam Server (Integrated NIC)"]: cron func started
[DEBUG] 2024/08/01 10:00:00 cronjobs.go:122: [CRON2 "Veeam Server (Integrated NIC)"]: got record from db
[DEBUG] 2024/08/01 10:00:00 cronjobs.go:125: [CRON3 "Veeam Server (Integrated NIC)"]: status is online
[DEBUG] 2024/08/01 10:00:00 cronjobs.go:127: [CRON3.5 "Veeam Server (Integrated NIC)"]: skipping run because already pending
[DEBUG] 2024/08/01 10:28:00 cronjobs.go:116: [CRON1 "Veeam Server (Integrated NIC)"]: cron func started
[DEBUG] 2024/08/01 10:28:00 cronjobs.go:122: [CRON2 "Veeam Server (Integrated NIC)"]: got record from db
[DEBUG] 2024/08/01 10:28:00 cronjobs.go:125: [CRON3 "Veeam Server (Integrated NIC)"]: status is offline
[DEBUG] 2024/08/01 10:28:00 cronjobs.go:135: [CRON4 "Veeam Server (Integrated NIC)"]: saved status pending
[INFO] 2024/08/01 10:28:00 wake.go:16: Wake triggered for Veeam Server (Integrated NIC)
[ERROR] 2024/08/01 10:30:00 cronjobs.go:137: Veeam Server (Integrated NIC)%!(EXTRA string=not online after 2 min)
[DEBUG] 2024/08/01 10:30:00 cronjobs.go:142: [CRON5 "Veeam Server (Integrated NIC)"]: wake device done
[DEBUG] 2024/08/01 10:30:00 cronjobs.go:146: [CRON6 "Veeam Server (Integrated NIC)"]: saved device
[DEBUG] 2024/08/01 11:28:00 cronjobs.go:116: [CRON1 "Veeam Server (Integrated NIC)"]: cron func started
[DEBUG] 2024/08/01 11:28:00 cronjobs.go:122: [CRON2 "Veeam Server (Integrated NIC)"]: got record from db
[DEBUG] 2024/08/01 11:28:00 cronjobs.go:125: [CRON3 "Veeam Server (Integrated NIC)"]: status is offline
[DEBUG] 2024/08/01 11:28:00 cronjobs.go:135: [CRON4 "Veeam Server (Integrated NIC)"]: saved status pending
[INFO] 2024/08/01 11:28:00 wake.go:16: Wake triggered for Veeam Server (Integrated NIC)
[ERROR] 2024/08/01 11:30:01 cronjobs.go:137: Veeam Server (Integrated NIC)%!(EXTRA string=not online after 2 min)
[DEBUG] 2024/08/01 11:30:01 cronjobs.go:142: [CRON5 "Veeam Server (Integrated NIC)"]: wake device done
[DEBUG] 2024/08/01 11:30:01 cronjobs.go:146: [CRON6 "Veeam Server (Integrated NIC)"]: saved device
[DEBUG] 2024/08/01 12:28:00 cronjobs.go:116: [CRON1 "Veeam Server (Integrated NIC)"]: cron func started
[DEBUG] 2024/08/01 12:28:00 cronjobs.go:122: [CRON2 "Veeam Server (Integrated NIC)"]: got record from db
[DEBUG] 2024/08/01 12:28:00 cronjobs.go:125: [CRON3 "Veeam Server (Integrated NIC)"]: status is offline
[DEBUG] 2024/08/01 12:28:00 cronjobs.go:135: [CRON4 "Veeam Server (Integrated NIC)"]: saved status pending
[INFO] 2024/08/01 12:28:00 wake.go:16: Wake triggered for Veeam Server (Integrated NIC)
[ERROR] 2024/08/01 12:30:01 cronjobs.go:137: Veeam Server (Integrated NIC)%!(EXTRA string=not online after 2 min)
[DEBUG] 2024/08/01 12:30:01 cronjobs.go:142: [CRON5 "Veeam Server (Integrated NIC)"]: wake device done
[DEBUG] 2024/08/01 12:30:01 cronjobs.go:146: [CRON6 "Veeam Server (Integrated NIC)"]: saved device
[DEBUG] 2024/08/01 13:28:00 cronjobs.go:116: [CRON1 "Veeam Server (Integrated NIC)"]: cron func started
[DEBUG] 2024/08/01 13:28:00 cronjobs.go:122: [CRON2 "Veeam Server (Integrated NIC)"]: got record from db
[DEBUG] 2024/08/01 13:28:00 cronjobs.go:125: [CRON3 "Veeam Server (Integrated NIC)"]: status is offline
[DEBUG] 2024/08/01 13:28:00 cronjobs.go:135: [CRON4 "Veeam Server (Integrated NIC)"]: saved status pending
[INFO] 2024/08/01 13:28:00 wake.go:16: Wake triggered for Veeam Server (Integrated NIC)
[ERROR] 2024/08/01 13:30:01 cronjobs.go:137: Veeam Server (Integrated NIC)%!(EXTRA string=not online after 2 min)
[DEBUG] 2024/08/01 13:30:01 cronjobs.go:142: [CRON5 "Veeam Server (Integrated NIC)"]: wake device done
[DEBUG] 2024/08/01 13:30:01 cronjobs.go:146: [CRON6 "Veeam Server (Integrated NIC)"]: saved device
[DEBUG] 2024/08/01 14:28:00 cronjobs.go:116: [CRON1 "Veeam Server (Integrated NIC)"]: cron func started
[DEBUG] 2024/08/01 14:28:00 cronjobs.go:122: [CRON2 "Veeam Server (Integrated NIC)"]: got record from db
[DEBUG] 2024/08/01 14:28:00 cronjobs.go:125: [CRON3 "Veeam Server (Integrated NIC)"]: status is offline
[DEBUG] 2024/08/01 14:28:00 cronjobs.go:135: [CRON4 "Veeam Server (Integrated NIC)"]: saved status pending
[INFO] 2024/08/01 14:28:00 wake.go:16: Wake triggered for Veeam Server (Integrated NIC)
[ERROR] 2024/08/01 14:30:01 cronjobs.go:137: Veeam Server (Integrated NIC)%!(EXTRA string=not online after 2 min)
[DEBUG] 2024/08/01 14:30:01 cronjobs.go:142: [CRON5 "Veeam Server (Integrated NIC)"]: wake device done
[DEBUG] 2024/08/01 14:30:01 cronjobs.go:146: [CRON6 "Veeam Server (Integrated NIC)"]: saved device
[DEBUG] 2024/08/01 15:28:00 cronjobs.go:116: [CRON1 "Veeam Server (Integrated NIC)"]: cron func started
[DEBUG] 2024/08/01 15:28:00 cronjobs.go:122: [CRON2 "Veeam Server (Integrated NIC)"]: got record from db
[DEBUG] 2024/08/01 15:28:00 cronjobs.go:125: [CRON3 "Veeam Server (Integrated NIC)"]: status is offline
[DEBUG] 2024/08/01 15:28:00 cronjobs.go:135: [CRON4 "Veeam Server (Integrated NIC)"]: saved status pending
[INFO] 2024/08/01 15:28:00 wake.go:16: Wake triggered for Veeam Server (Integrated NIC)
[ERROR] 2024/08/01 15:30:01 cronjobs.go:137: Veeam Server (Integrated NIC)%!(EXTRA string=not online after 2 min)
[DEBUG] 2024/08/01 15:30:01 cronjobs.go:142: [CRON5 "Veeam Server (Integrated NIC)"]: wake device done
[DEBUG] 2024/08/01 15:30:01 cronjobs.go:146: [CRON6 "Veeam Server (Integrated NIC)"]: saved device
levelsw commented 1 month ago

It’s not failing anymore. It ran each evening until now. I will try to make some changes to see if it keeps working

levelsw commented 3 weeks ago

For me strangely enough it doesn't break since testing out the beta version. Stopped and restarted the container just in case a couple days ago as well. Are you testing this version as well @kraizelburg ? Does it fail for you?

kraizelburg commented 3 weeks ago

For me strangely enough it doesn't break since testing out the beta version. Stopped and restarted the container just in case a couple days ago as well. Are you testing this version as well @kraizelburg ? Does it fail for you?

I am testing it, so far today executed wake cron without any problem, let's see tomorrow.

kraizelburg commented 3 weeks ago

Hi, unfortunately wake cron this morning did not triggered in the new beta.

levelsw commented 3 weeks ago

Hi, unfortunately wake cron this morning did not triggered in the new beta.

Probably @seriousm4x will be asking for the logs of the upsnap container as he added verbose logging to the console. Can you add the container logs?

kraizelburg commented 3 weeks ago

Hi, unfortunately wake cron this morning did not triggered in the new beta.

Probably @seriousm4x will be asking for the logs of the upsnap container as he added verbose logging to the console. Can you add the container logs?

I had to edit the commend as today it did not triggered the wake cron again. it seems it only works first time you deploy the container but not after. what does "skipping run because already pending" mean?


2024/08/14 08:52:41 Server started at http://0.0.0.0:8090
├─ REST API: http://0.0.0.0:8090/api/
└─ Admin UI: http://0.0.0.0:8090/_/
[INFO] 2024/08/14 17:51:33 wake.go:16: Wake triggered for Dell Optiplex Server
[DEBUG] 2024/08/15 07:05:27 cronjobs.go:116: [CRON1 "Dell Optiplex Server"]: cron func started
[DEBUG] 2024/08/15 07:05:27 cronjobs.go:122: [CRON2 "Dell Optiplex Server"]: got record from db
[DEBUG] 2024/08/15 07:05:27 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is offline
[DEBUG] 2024/08/15 07:05:27 cronjobs.go:135: [CRON4 "Dell Optiplex Server"]: saved status pending
[INFO] 2024/08/15 07:05:27 wake.go:16: Wake triggered for Dell Optiplex Server
[DEBUG] 2024/08/15 07:05:58 cronjobs.go:142: [CRON5 "Dell Optiplex Server"]: wake device done
[DEBUG] 2024/08/15 07:05:58 cronjobs.go:146: [CRON6 "Dell Optiplex Server"]: saved device
[DEBUG] 2024/08/16 07:05:46 cronjobs.go:116: [CRON1 "Dell Optiplex Server"]: cron func started
[DEBUG] 2024/08/16 07:05:47 cronjobs.go:122: [CRON2 "Dell Optiplex Server"]: got record from db
[DEBUG] 2024/08/16 07:05:47 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is online
[DEBUG] 2024/08/16 07:05:47 cronjobs.go:127: [CRON3.5 "Dell Optiplex Server"]: skipping run because already pending```
seriousm4x commented 2 weeks ago

what does "skipping run because already pending" mean?

I should have written "skipping run because device is not offline". Meaning that the wake cron makes no sense to run because device is either online or already waking up or shutting down.

kraizelburg commented 2 weeks ago

what does "skipping run because already pending" mean?

I should have written "skipping run because device is not offline". Meaning that the wake cron makes no sense to run because device is either online or already waking up or shutting down.

Hi, I have been testing the new build a few more days and now I can certanly say that there is a pattern as it work one day but not the following then it works again. Everytime I see "skipping run because already pending" it doe not work for that day.


2024/08/14 08:52:41 Server started at http://0.0.0.0:8090
├─ REST API: http://0.0.0.0:8090/api/
└─ Admin UI: http://0.0.0.0:8090/_/
[INFO] 2024/08/14 17:51:33 wake.go:16: Wake triggered for Dell Optiplex Server
[DEBUG] 2024/08/15 07:05:27 cronjobs.go:116: [CRON1 "Dell Optiplex Server"]: cron func started
[DEBUG] 2024/08/15 07:05:27 cronjobs.go:122: [CRON2 "Dell Optiplex Server"]: got record from db
[DEBUG] 2024/08/15 07:05:27 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is offline
[DEBUG] 2024/08/15 07:05:27 cronjobs.go:135: [CRON4 "Dell Optiplex Server"]: saved status pending
[INFO] 2024/08/15 07:05:27 wake.go:16: Wake triggered for Dell Optiplex Server
[DEBUG] 2024/08/15 07:05:58 cronjobs.go:142: [CRON5 "Dell Optiplex Server"]: wake device done
[DEBUG] 2024/08/15 07:05:58 cronjobs.go:146: [CRON6 "Dell Optiplex Server"]: saved device
[DEBUG] 2024/08/16 07:05:46 cronjobs.go:116: [CRON1 "Dell Optiplex Server"]: cron func started
[DEBUG] 2024/08/16 07:05:47 cronjobs.go:122: [CRON2 "Dell Optiplex Server"]: got record from db
[DEBUG] 2024/08/16 07:05:47 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is online
[DEBUG] 2024/08/16 07:05:47 cronjobs.go:127: [CRON3.5 "Dell Optiplex Server"]: skipping run because already pending
[DEBUG] 2024/08/17 07:05:45 cronjobs.go:116: [CRON1 "Dell Optiplex Server"]: cron func started
[DEBUG] 2024/08/17 07:05:45 cronjobs.go:122: [CRON2 "Dell Optiplex Server"]: got record from db
[DEBUG] 2024/08/17 07:05:45 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is offline
[DEBUG] 2024/08/17 07:05:45 cronjobs.go:135: [CRON4 "Dell Optiplex Server"]: saved status pending
[INFO] 2024/08/17 07:05:45 wake.go:16: Wake triggered for Dell Optiplex Server
[DEBUG] 2024/08/17 07:06:14 cronjobs.go:142: [CRON5 "Dell Optiplex Server"]: wake device done
[DEBUG] 2024/08/17 07:06:14 cronjobs.go:146: [CRON6 "Dell Optiplex Server"]: saved device
[DEBUG] 2024/08/18 07:05:18 cronjobs.go:116: [CRON1 "Dell Optiplex Server"]: cron func started
[DEBUG] 2024/08/18 07:05:18 cronjobs.go:122: [CRON2 "Dell Optiplex Server"]: got record from db
[DEBUG] 2024/08/18 07:05:18 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is online
[DEBUG] 2024/08/18 07:05:18 cronjobs.go:127: [CRON3.5 "Dell Optiplex Server"]: skipping run because already pending
[DEBUG] 2024/08/19 07:05:47 cronjobs.go:116: [CRON1 "Dell Optiplex Server"]: cron func started
[DEBUG] 2024/08/19 07:05:47 cronjobs.go:122: [CRON2 "Dell Optiplex Server"]: got record from db
[DEBUG] 2024/08/19 07:05:47 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is offline
[DEBUG] 2024/08/19 07:05:47 cronjobs.go:135: [CRON4 "Dell Optiplex Server"]: saved status pending
[INFO] 2024/08/19 07:05:47 wake.go:16: Wake triggered for Dell Optiplex Server
[DEBUG] 2024/08/19 07:06:17 cronjobs.go:142: [CRON5 "Dell Optiplex Server"]: wake device done
[DEBUG] 2024/08/19 07:06:17 cronjobs.go:146: [CRON6 "Dell Optiplex Server"]: saved device
[DEBUG] 2024/08/20 07:04:59 cronjobs.go:116: [CRON1 "Dell Optiplex Server"]: cron func started
[DEBUG] 2024/08/20 07:04:59 cronjobs.go:122: [CRON2 "Dell Optiplex Server"]: got record from db
[DEBUG] 2024/08/20 07:04:59 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is offline
[DEBUG] 2024/08/20 07:04:59 cronjobs.go:135: [CRON4 "Dell Optiplex Server"]: saved status pending
[INFO] 2024/08/20 07:04:59 wake.go:16: Wake triggered for Dell Optiplex Server
[DEBUG] 2024/08/20 07:05:32 cronjobs.go:142: [CRON5 "Dell Optiplex Server"]: wake device done
[DEBUG] 2024/08/20 07:05:32 cronjobs.go:146: [CRON6 "Dell Optiplex Server"]: saved device
[DEBUG] 2024/08/21 07:05:49 cronjobs.go:116: [CRON1 "Dell Optiplex Server"]: cron func started
[DEBUG] 2024/08/21 07:05:49 cronjobs.go:122: [CRON2 "Dell Optiplex Server"]: got record from db
[DEBUG] 2024/08/21 07:05:49 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is online
[DEBUG] 2024/08/21 07:05:49 cronjobs.go:127: [CRON3.5 "Dell Optiplex Server"]: skipping run because already pending```
seriousm4x commented 2 weeks ago

Thanks for your effort in testing this. What is strange for me is that the device is always displayed as online. I assume that the server is actually offline? Then the wrong status would be the reason for this.

[DEBUG] 2024/08/16 07:05:47 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is online
[DEBUG] 2024/08/16 07:05:47 cronjobs.go:127: [CRON3.5 "Dell Optiplex Server"]: skipping run because already pending
...
[DEBUG] 2024/08/18 07:05:18 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is online
[DEBUG] 2024/08/18 07:05:18 cronjobs.go:127: [CRON3.5 "Dell Optiplex Server"]: skipping run because already pending
...
[DEBUG] 2024/08/21 07:05:49 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is online
[DEBUG] 2024/08/21 07:05:49 cronjobs.go:127: [CRON3.5 "Dell Optiplex Server"]: skipping run because already pending

I think a pointer problem is the reason for this. I've pushed a new beta which hopefully finally fixes this :) Please let me know if it works now.

kraizelburg commented 2 weeks ago

Thanks for your effort in testing this. What is strange for me is that the device is always displayed as online. I assume that the server is actually offline? Then the wrong status would be the reason for this.

[DEBUG] 2024/08/16 07:05:47 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is online
[DEBUG] 2024/08/16 07:05:47 cronjobs.go:127: [CRON3.5 "Dell Optiplex Server"]: skipping run because already pending
...
[DEBUG] 2024/08/18 07:05:18 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is online
[DEBUG] 2024/08/18 07:05:18 cronjobs.go:127: [CRON3.5 "Dell Optiplex Server"]: skipping run because already pending
...
[DEBUG] 2024/08/21 07:05:49 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is online
[DEBUG] 2024/08/21 07:05:49 cronjobs.go:127: [CRON3.5 "Dell Optiplex Server"]: skipping run because already pending

I think a pointer problem is the reason for this. I've pushed a new beta which hopefully finally fixes this :) Please let me know if it works now.

Yes, the server shutdown every night at 1am.

levelsw commented 2 weeks ago

Just my 2 cents, I enabled Intel AMT on the target machine at some point, which caused the target to always respond to pings. This didn't trigger the wake anymore but I just use a not used IP for now so that it keeps being triggered every day. It still just works for me for some reason, I can't get it to fail at the moment

kraizelburg commented 2 weeks ago

Thanks for your effort in testing this. What is strange for me is that the device is always displayed as online. I assume that the server is actually offline? Then the wrong status would be the reason for this.

[DEBUG] 2024/08/16 07:05:47 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is online
[DEBUG] 2024/08/16 07:05:47 cronjobs.go:127: [CRON3.5 "Dell Optiplex Server"]: skipping run because already pending
...
[DEBUG] 2024/08/18 07:05:18 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is online
[DEBUG] 2024/08/18 07:05:18 cronjobs.go:127: [CRON3.5 "Dell Optiplex Server"]: skipping run because already pending
...
[DEBUG] 2024/08/21 07:05:49 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is online
[DEBUG] 2024/08/21 07:05:49 cronjobs.go:127: [CRON3.5 "Dell Optiplex Server"]: skipping run because already pending

I think a pointer problem is the reason for this. I've pushed a new beta which hopefully finally fixes this :) Please let me know if it works now.

Hi again, I am afraid to say that new beta 3 is not working either. Then log shows that upsnap thinks the device is online when it is not.

'''[INFO] 2024/08/21 09:54:46 pb.go:280: Ping interval set to @every 3s
2024/08/21 09:54:46 Server started at http://0.0.0.0:8090
├─ REST API: http://0.0.0.0:8090/api/
└─ Admin UI: http://0.0.0.0:8090/_/
[DEBUG] 2024/08/22 07:05:13 cronjobs.go:116: [CRON1 "Dell Optiplex Server"]: cron func started
[DEBUG] 2024/08/22 07:05:13 cronjobs.go:122: [CRON2 "Dell Optiplex Server"]: got record from db
[DEBUG] 2024/08/22 07:05:13 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is online
[DEBUG] 2024/08/22 07:05:13 cronjobs.go:127: [CRON3.5 "Dell Optiplex Server"]: skipping run because device is not offline'''
seriousm4x commented 2 weeks ago

Ok, I'm confused. Could you login to the admin backend at localhost:8090/_/, then devices and check if the status of your server is online? Also, what state does the normal upsnap dashboard show? Is it correctly showing online/offline?

kraizelburg commented 2 weeks ago

Hi, now it is online because I triggered the wake command manually but it was offline for sure as the server shutdown every night. I will check this tomorrow. Regarding the status on the dashboard the power button was red this morning, now it is green because I manually pressed it.

El 22 ago 2024, a las 11:58, seriousm4x @.***> escribió:

Ok, I'm confused. Could you login to the admin backend at localhost:8090/_/, then devices and check if the status of your server is online? Also, what state does the normal upsnap dashboard show? Is it correctly showing online/offline?

— Reply to this email directly, view it on GitHubhttps://github.com/seriousm4x/UpSnap/issues/669#issuecomment-2304262186, or unsubscribehttps://github.com/notifications/unsubscribe-auth/ATL6H2FN3WVWQZBDZPVI3CTZSWY5XAVCNFSM6AAAAABKXEGPWOVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDGMBUGI3DEMJYGY. You are receiving this because you were mentioned.Message ID: @.***>

kraizelburg commented 1 week ago

Hi, I just wanted to report that it has been working for a couple of days now, it seems that it's fixed.

[DEBUG] 2024/08/25 07:03:36 cronjobs.go:122: [CRON2 "Dell Optiplex Server"]: got record from db
[DEBUG] 2024/08/25 07:03:36 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is offline
[DEBUG] 2024/08/25 07:03:36 cronjobs.go:135: [CRON4 "Dell Optiplex Server"]: saved status pending
[INFO] 2024/08/25 07:03:36 wake.go:16: Wake triggered for Dell Optiplex Server
[DEBUG] 2024/08/25 07:04:06 cronjobs.go:142: [CRON5 "Dell Optiplex Server"]: wake device done
[DEBUG] 2024/08/25 07:04:06 cronjobs.go:146: [CRON6 "Dell Optiplex Server"]: saved device
[DEBUG] 2024/08/26 07:04:49 cronjobs.go:116: [CRON1 "Dell Optiplex Server"]: cron func started
[DEBUG] 2024/08/26 07:04:49 cronjobs.go:122: [CRON2 "Dell Optiplex Server"]: got record from db
[DEBUG] 2024/08/26 07:04:49 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is offline
[DEBUG] 2024/08/26 07:04:49 cronjobs.go:135: [CRON4 "Dell Optiplex Server"]: saved status pending
[INFO] 2024/08/26 07:04:49 wake.go:16: Wake triggered for Dell Optiplex Server
[DEBUG] 2024/08/26 07:05:18 cronjobs.go:142: [CRON5 "Dell Optiplex Server"]: wake device done
[DEBUG] 2024/08/26 07:05:18 cronjobs.go:146: [CRON6 "Dell Optiplex Server"]: saved device
kraizelburg commented 1 week ago

Hi, today wake cron did not work again, it is very erratic and I cannot figure out why. Today again skipping because it thinks that device is not offline when it clearly it is.

Captura de pantalla 2024-08-27 a las 8 41 46


[DEBUG] 2024/08/25 07:03:36 cronjobs.go:122: [CRON2 "Dell Optiplex Server"]: got record from db
[DEBUG] 2024/08/25 07:03:36 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is offline
[DEBUG] 2024/08/25 07:03:36 cronjobs.go:135: [CRON4 "Dell Optiplex Server"]: saved status pending
[INFO] 2024/08/25 07:03:36 wake.go:16: Wake triggered for Dell Optiplex Server
[DEBUG] 2024/08/25 07:04:06 cronjobs.go:142: [CRON5 "Dell Optiplex Server"]: wake device done
[DEBUG] 2024/08/25 07:04:06 cronjobs.go:146: [CRON6 "Dell Optiplex Server"]: saved device
[DEBUG] 2024/08/26 07:04:49 cronjobs.go:116: [CRON1 "Dell Optiplex Server"]: cron func started
[DEBUG] 2024/08/26 07:04:49 cronjobs.go:122: [CRON2 "Dell Optiplex Server"]: got record from db
[DEBUG] 2024/08/26 07:04:49 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is offline
[DEBUG] 2024/08/26 07:04:49 cronjobs.go:135: [CRON4 "Dell Optiplex Server"]: saved status pending
[INFO] 2024/08/26 07:04:49 wake.go:16: Wake triggered for Dell Optiplex Server
[DEBUG] 2024/08/26 07:05:18 cronjobs.go:142: [CRON5 "Dell Optiplex Server"]: wake device done
[DEBUG] 2024/08/26 07:05:18 cronjobs.go:146: [CRON6 "Dell Optiplex Server"]: saved device
[DEBUG] 2024/08/27 07:04:55 cronjobs.go:116: [CRON1 "Dell Optiplex Server"]: cron func started
[DEBUG] 2024/08/27 07:04:55 cronjobs.go:122: [CRON2 "Dell Optiplex Server"]: got record from db
[DEBUG] 2024/08/27 07:04:55 cronjobs.go:125: [CRON3 "Dell Optiplex Server"]: status is online
[DEBUG] 2024/08/27 07:04:55 cronjobs.go:127: [CRON3.5 "Dell Optiplex Server"]: skipping run because device is not offline```
seriousm4x commented 1 week ago

Definitely sounds like a pointer issue in my go code 🤔 That'd explain the randomness and mismatched states.

Pushed another attempt to fix this 4.2.13-beta.4

kraizelburg commented 1 week ago

Definitely sounds like a pointer issue in my go code 🤔 That'd explain the randomness and mismatched states.

Pushed another attempt to fix this 4.2.13-beta.4

Thank you for the effort but again I tried and it is not working. Same story... it was working perfectly fine until version 3 I wonder what happened in the migration to v4


2024/08/28 07:53:34 Server started at http://0.0.0.0:8090
├─ REST API: http://0.0.0.0:8090/api/
└─ Admin UI: http://0.0.0.0:8090/_/
[INFO] 2024/08/28 07:54:49 wake.go:16: Wake triggered for Dell Optiplex Server
[DEBUG] 2024/08/29 07:04:48 cronjobs.go:118: [CRON1 "Dell Optiplex Server"]: cron func started
[DEBUG] 2024/08/29 07:04:49 cronjobs.go:124: [CRON2 "Dell Optiplex Server"]: got record from db
[DEBUG] 2024/08/29 07:04:49 cronjobs.go:127: [CRON3 "Dell Optiplex Server"]: status is online
[DEBUG] 2024/08/29 07:04:49 cronjobs.go:129: [CRON3.5 "Dell Optiplex Server"]: skipping run because device is not offline```
seriousm4x commented 2 days ago

Do you guys have "Lazy ping" enabled in /settings? If that option is enabled, the device status will not be updated because no client is connected to the dashboard. That would also explain the issue. For example:

kraizelburg commented 2 days ago

Do you guys have "Lazy ping" enabled in /settings? If that option is enabled, the device status will not be updated because no client is connected to the dashboard. That would also explain the issue. For example:

  • Client has the dashboard open with device online
  • Client disconnects, upsnap will no longer ping devices, therefore the device will remain online
  • Device will tun off -> upsnap will not notice it
  • Cronjob runs -> skipps because status is still online in the database

Hi, yes I had lazy ping enabled so that may be why devices were not woken up. I just installed latest beta 5 and I will report back. Thanks

seriousm4x commented 2 days ago

yes I had lazy ping enabled

Ok, I'm pretty sure that's the issue then, because I was able to reproduce it with lazy ping enabled. Before you try beta 5, I've pushed beta 6. Please try this instead once the build is done.

levelsw commented 2 days ago

Do you guys have "Lazy ping" enabled in /settings? If that option is enabled, the device status will not be updated because no client is connected to the dashboard. That would also explain the issue. For example:

  • Client has the dashboard open with device online
  • Client disconnects, upsnap will no longer ping devices, therefore the device will remain online
  • Device will tun off -> upsnap will not notice it
  • Cronjob runs -> skipps because status is still online in the database

I don’t have lazy ping enabled at the moment and it’s also not failing for me. I can’t say for sure that I turned off lazy ping at some point. I know I was looking at it that option before. So probably I fixed the issue at some point by trying with lazy ping disabled. I can turn it on again if you want me to test the last beta with lazy ping, let me know

seriousm4x commented 2 days ago

I can turn it on again if you want me to test the last beta with lazy ping, let me know

That'd be awesome! Thanks