Log files

[cw-kid]

I am having issues with a shell command. I installed ps4-waker on to the same Debian box as MSR. Its a utility to turn on the Playstation4 console as Sony block 3rd party remotes like Harmony from doing it.

I have two rules setup in MSR, one that turns on the PS4 when the associated Harmony Activity is starting (Vera Harmony plugin).

The shell command that is sent in this rule is just:

ps4-waker

This works most of the time OK, but sometimes for some reason the PS4 doesn't turn on every time.

I then had another rule and I wanted to see if I could extract some information? from the ps4-waker utility about the status of the PS4. The shell command for this one is:

ps4-waker check

In the rule I get "null"

This is the one that isn't working currently. In the log it says:

<Engine:ERR> Engine#1 reaction PS4 Waker Check<SET> step 0 error executing shell `ps4-waker check': Error: Command failed: ps4-waker check

If I run this command directly in terminal it works fine every time:

As a quick test I changed the shell command to this one and that does work OK

ps4-waker --help

This is the --help output of the switches and options:

Thanks

[toggledbits]

Look for other messages in the log file before the one you pasted.

[cw-kid]

@toggledbits

Here is a bit more of the log:

2021-07-30T14:06:29.372Z <Engine:ERR> Engine#1 reaction PS4 Waker Check<SET> step 0 error executing shell `ps4-waker check': Error: Command failed: ps4-waker check
2021-07-30T14:06:29.375Z <Rule:5:Rule.js:674> Rule#rule-krq612qx rule set variable ps4wakercheck = (object) (null)
2021-07-30T14:06:29.376Z <Engine:5:Engine.js:940> Engine#1 set variable rule rule-krq612qx ps4wakercheck=(null), requesting re-eval
2021-07-30T14:06:29.377Z <Rule:5:Rule.js:962> Rule#rule-krq612qx (PS4 Waker Check) evaluate() acquiring mutex
2021-07-30T14:06:29.378Z <Engine:5:Engine.js:1140> _process_reaction_queue() wake-up!
2021-07-30T14:06:29.379Z <Rule:5:Rule.js:966> Rule#rule-krq612qx._evaluate() mutex acquired, evaluating
2021-07-30T14:06:29.380Z <Rule:5:Rule.js:970> Rule#rule-krq612qx update rate is 2/min limit 60/min
2021-07-30T14:06:29.381Z <Rule:5:Rule.js:892> Rule#rule-krq612qx evaluateExpressions() with 1 expressions
2021-07-30T14:06:29.382Z <Rule:5:Rule.js:1600> cond condbefy480 evaluation state false->true
2021-07-30T14:06:29.383Z <Rule:5:Rule.js:1600> cond trig evaluation state false->true
2021-07-30T14:06:29.383Z <Rule:5:Rule.js:982> Rule#rule-krq612qx._evaluate() trigger state now true (was false)
2021-07-30T14:06:29.384Z <Rule:5:Rule.js:984> Rule#rule-krq612qx._evaluate() constraints state true
2021-07-30T14:06:29.384Z <Rule:5:Rule.js:988> Rule#rule-krq612qx ready to set, constraints met
2021-07-30T14:06:29.385Z <Rule:5:Rule.js:991> Rule#rule-krq612qx rule state changed, was false now true
2021-07-30T14:06:29.385Z <Rule:INFO> PS4 Waker Check (Rule#rule-krq612qx) SET!
2021-07-30T14:06:29.386Z <Rule:5:Rule.js:993> Rule#rule-krq612qx rule state now true, changed true
2021-07-30T14:06:29.391Z <Engine:5:Engine.js:1101> _process_reaction_queue() running task 37 { "tid": 37, "id": "rule-krq612qx:S", "rule": "rule-krq612qx", "__reaction": [RuleReaction#rule-krq612qx:S], "next_step": 1, "status": 1, "ts": 1627653988822, "parent": --null--, "__resolve": --function--, "__reject": --function--, "__promise": [object Promise], "attempts": 1 }
2021-07-30T14:06:29.391Z <Engine:NOTICE> Resuming reaction PS4 Waker Check<SET> (rule-krq612qx:S) from step 1
2021-07-30T14:06:29.391Z <Engine:INFO> PS4 Waker Check<SET> all actions completed.
2021-07-30T14:06:29.392Z <Engine:5:Engine.js:1105> _process_reaction_queue() task returned, new status -1; task 37
2021-07-30T14:06:29.395Z <Engine:5:Engine.js:1140> _process_reaction_queue ending with 0 in queue; none delayed/ready; waiting
2021-07-30T14:06:29.396Z <Rule:5:Rule.js:1010> Rule#rule-krq612qx enqueueing reaction rule-krq612qx:S
2021-07-30T14:06:29.396Z <Engine:INFO> Enqueueing "PS4 Waker Check<SET>" (rule-krq612qx:S)
2021-07-30T14:06:29.398Z <Engine:5:Engine.js:985> Engine#1 enqueued reaction rule-krq612qx:S as 38
2021-07-30T14:06:29.399Z <Engine:5:Engine.js:1140> _process_reaction_queue() wake-up!
2021-07-30T14:06:29.400Z <Engine:5:Engine.js:1101> _process_reaction_queue() running task 38 { "tid": 38, "id": "rule-krq612qx:S", "rule": "rule-krq612qx", "__reaction": [RuleReaction#rule-krq612qx:S], "next_step": 0, "status": 0, "ts": 1627653989396, "parent": --null--, "__resolve": --function--, "__reject": --function--, "__promise": [object Promise] }
2021-07-30T14:06:29.401Z <Engine:NOTICE> Starting reaction PS4 Waker Check<SET> (rule-krq612qx:S)
2021-07-30T14:06:29.402Z <Engine:5:Engine.js:1378> Engine#1 reaction rule-krq612qx:S step 0 shell command { "command": "ps4-waker check", "rule": "rule-krq612qx", "rvar": "ps4wakercheck" }
2021-07-30T14:06:29.419Z <Engine:5:Engine.js:1105> _process_reaction_queue() task returned, new status 3; task 38
2021-07-30T14:06:29.422Z <Engine:5:Engine.js:1140> _process_reaction_queue ending with 1 in queue; none delayed/ready; waiting
2021-07-30T14:06:29.424Z <Rule:5:Rule.js:762> Rule#rule-krq612qx dependency notification timer-trigger Timer#rule-krq612qx from Timer#rule-krq612qx
2021-07-30T14:06:29.424Z <Rule:5:Rule.js:768> Rule#rule-krq612qx requesting eval; timer-trigger Timer#rule-krq612qx
2021-07-30T14:06:29.425Z <Rule:5:Rule.js:962> Rule#rule-krq612qx (PS4 Waker Check) evaluate() acquiring mutex
2021-07-30T14:06:29.426Z <Rule:5:Rule.js:966> Rule#rule-krq612qx._evaluate() mutex acquired, evaluating
2021-07-30T14:06:29.427Z <Rule:5:Rule.js:970> Rule#rule-krq612qx update rate is 3/min limit 60/min
2021-07-30T14:06:29.428Z <Rule:5:Rule.js:892> Rule#rule-krq612qx evaluateExpressions() with 1 expressions
2021-07-30T14:06:29.429Z <Rule:5:Rule.js:1600> cond condbefy480 evaluation state true->false
2021-07-30T14:06:29.430Z <Rule:5:Rule.js:1600> cond trig evaluation state true->false
2021-07-30T14:06:29.431Z <Rule:5:Rule.js:982> Rule#rule-krq612qx._evaluate() trigger state now false (was true)
2021-07-30T14:06:29.431Z <Rule:5:Rule.js:984> Rule#rule-krq612qx._evaluate() constraints state true
2021-07-30T14:06:29.432Z <Rule:5:Rule.js:990> Rule#rule-krq612qx trigger conditions not met
2021-07-30T14:06:29.433Z <Rule:5:Rule.js:991> Rule#rule-krq612qx rule state changed, was true now false
2021-07-30T14:06:29.433Z <Rule:INFO> PS4 Waker Check (Rule#rule-krq612qx) RESET!
2021-07-30T14:06:29.434Z <Rule:5:Rule.js:993> Rule#rule-krq612qx rule state now false, changed true
2021-07-30T14:06:29.945Z <Engine:ERR> Engine#1 reaction PS4 Waker Check<SET> step 0 error executing shell `ps4-waker check': Error: Command failed: ps4-waker check

[toggledbits]

Nothing really of substance. That's pretty much all the output from the command. If it just fails randomly and occasionally, it's probably a device communications issue.

[cw-kid]

@toggledbits

No this "ps4-waker check" command I cannot get working at all with MSR. It always shows an error.

The other command "ps4-waker" does work most of the time.

[cw-kid]

I have two different rulesets.

This is the working one:

However the other rule with "check" on the end of the command has never worked and errors.

I always see these Alerts:

[toggledbits]

Could it be that "check" returns a non-zero exit code depending on its result? Many utilities do this. A non-zero exit code would be interpreted as an error by MSR.

[cw-kid]

@toggledbits

I'm not sure, when I run the check command in terminal it always outputs something like this:

{
  "type": "device",
  "statusLine": "620 Server Standby",
  "statusCode": "620",
  "status": "Standby",
  "host-id": "C863F1400EF1",
  "host-type": "PS4",
  "host-name": "PS4-806",
  "host-request-port": "997",
  "device-discovery-protocol-version": "00020020",
  "system-version": "08520011",
  "address": "192.168.0.201"
}

statusline "620 Server Standby" means the PS4 is currently in sleep mode.

Think it says "200 OK" when the PS4 is turned on and running.

I was wondering if I could extract that device power status using MSR and then maybe send it to a virtual device in Vera / Home Remote etc.

Also that check command can tell you which app is currently opened on the PS4 and also possibly which game is currently being played.

But its not required I guess, I just wanted to see if it could be done somehow.

The main thing is the PS4 is turned on when the other MSR rule detects that my Harmony activity for the PS4 has started and that at the moment seems to be working OK.

[toggledbits]

Try running the command this way (yourself, in a shell, not in MSR):

    ps4-waker check ; echo $?

This will display the exit status of the command after it runs. You may need to run this repeatedly, under various different expectations of status, including testing when the device is disconnected/powered off, to get a complete feel for what shell exit status ps4-waker is returning under various conditions. Anything other than 0 is going to be a problem (it looks like an error). Using non-zero exit codes is a very common way for some utilities to return their status quickly so that shell scripts can make quick decisions without having to parse other data (like your output), so it's very likely that under some condition this script is working fine but returning non-zero. If that's the case, you're going to need a wrapper script to "deaden" the exit code.

I've also just pushed up a new build to latest that has additional logging for this action, so you can try that as well and see if it gives any new information. I would not upgrade to latest in lieu of doing the above, as I cannot display the exit code (at least, not that I've found, as yet), so the above test is still a necessary important step. This will simply add stderr output to the logging (although I suspect the prior error messages already contain all the relevant output -- this is a safety/assurance that we're seeing it).

[cw-kid]

@toggledbits

When the Playstation is in sleep mode:

When the Playstation is turned on and running:

Your right the MSR rule is working and returning data only when the Playstation is turned on:

I thought it wasn't working when turned on but clearly it now is.

So because the exit code is a 1 when the Playstation is turned off that is why the MSR rule then does not return any data?

Thanks

[toggledbits]

That's correct. Any non-zero is an error. I will add a checkbox to the action to (optionally) ignore the exit code, and make that available in a build later today.

[cw-kid]

@toggledbits

That's great thank you.

Next problem how to extract the data from the in rule expression and split out the PS4's power status out in to another expression ?

I guess either "statusLine" or "statusCode" could be used.

(string) "{\n \"type\": \"device\",\n \"statusLine\": \"200 Ok\",\n \"statusCode\": \"200\",\n \"status\": \"Ok\",\n \"host-id\": \"C863F1400EF1\",\n \"host-type\": \"PS4\",\n \"host-name\": \"PS4-806\",\n \"host-request-port\": \"997\",\n \"device-discovery-protocol-version\": \"00020020\",\n \"system-version\": \"08520011\",\n \"running-app-name\": \"Concrete Genie\",\n \"running-app-titleid\": \"CUSA11875\",\n \"address\": \"192.168.0.201\"\n}\n"

And you can see there is also a "running-app-name" Concrete Genie is the game being played currently.

[toggledbits]

Use another expression to put that string through the parseJSON() function and it will turn it into an object you can then pick the data out of.

[cw-kid]

@toggledbits said in Having issues with a shell command:

parseJSON()

Like this ?

Contents of the expression "ps4wakerparse"

Last value:(object) {"type":"device","statusLine":"200 Ok","statusCode":"200","status":"Ok","host-id":"C863F1400EF1","host-type":"PS4","host-name":"PS4-806","host-request-port":"997","device-discovery-protocol-version":"00020020","system-version":"08520011","running-app-name":"Concrete Genie","running-app-titleid":"CUSA11875","address":"192.168.0.201"}

[toggledbits]

I don't know what the first expression is/was, but the second one is correct and has parsed the value correctly. You can now refer to data in the object via ps4wakerparse.statusCode for example. For names that contain special characters, like host-id, you need to use the alternate (quoted identifier) syntax ps4wakerparse["host-id"]

[cw-kid]

@toggledbits

Seems to be working and pulling out the required data:

The first expression named "ps4wakercheck" is the inital output of the shell command "ps4-waker check".

[toggledbits]

OK. I see that it's not consistently clearing the error from some prior usage on ps4wakercheck, that's what's confusing/odd, so I've fixed that for today's build as well (PR 0000235).

[toggledbits]

By the way, it's much more efficient to use expressions in ps4powerstatus and ps4runningapp than it is to use Set Variable actions to set them. That's kind of doing it the hard way.

[cw-kid]

@toggledbits

For the value in the expression "ps4powerstatus" its either going to be:

200 = ON
620 = OFF

How can I have another expression that will translate those code numbers in to human text that I can then send to Vera / Home Remote ?

Thanks

[cw-kid]

@toggledbits said in Having issues with a shell command:

By the way, it's much more efficient to use expressions in ps4powerstatus and ps4runningapp

Understood I have changed it and removed the set variable actions:

EDIT:

Don't think it likes that, I get these error when I press the "Reset" button on the rule.