INFO message injected in JSON response

[k-bx]

The problem

Upon receiving a batch of messages, sometimes I get JSON which also contains an INFO message like this:

INFO IncomingMessageHandler - Ignoring a group message from an unauthorized sender (no member or admin)

which makes the JSON invalid.

Are you using the latest released version?

• [X] Yes

Have you read the troubleshooting page?

• [X] Yes

What type of installation are you running?

signal-cli-rest-api Docker Container

In which mode are you using the docker container?

Native Mode

What's the architecture of your host system?

x86-64

Additional information

No response

[bbernhard]

Thanks, I'll have a look!

[kxait]

Hi, having the same issue here on the /v1/receive endpoint, additionally, the response for a /v2/send request fails with 400 and error message {"error":"strconv.ParseInt: parsing \"INFO SignalAccount - Config file is in use by another instance, waiting…\\nINFO SignalAccount - Config file lock acquired.\\n1696717441700\": invalid syntax"} even though the message is actually sent

This problem occurs on 0.69, but 0.67 works fine

[bbernhard]

Hi, having the same issue here on the /v1/receive endpoint, additionally, the response for a /v2/send request fails with 400 and error message {"error":"strconv.ParseInt: parsing \"INFO SignalAccount - Config file is in use by another instance, waiting…\\nINFO SignalAccount - Config file lock acquired.\\n1696717441700\": invalid syntax"} even though the message is actually sent

This problem occurs on 0.69, but 0.67 works fine

That sounds like a different error. Do you have multiple signal-cli-rest-api docker containers running?

[kxait]

That sounds like a different error. Do you have multiple signal-cli-rest-api docker containers running?

nope, definitely had only one instance running

[Herbs851]

Hi @bbernhard @kxait,

I've seen these errors in two cases with Home Assistant :

1. If you use a notification group instead of sending a message to a signal group :

Ko with "platform group" like :

notify:

  - name: Signal foo
    platform: signal_messenger
    url: !secret sigurl
    number: !secret signum
    recipients: !secret sigfoo

  - name: Signal bar
    platform: signal_messenger
    url: !secret sigurl
    number: !secret signum
    recipients: !secret sigbar

  - name: group_notif
    platform: group
    services:
      - service: signal_foo
      - service: signal_bar

I think that in this case HA makes 2 requests too quickly.

I fixed the error by creating a group signal directly, end then replace my old group by :

notify:

  - name: group_signal
    platform: signal_messenger
    url: !secret sigurl
    number: !secret signum
    recipients: !secret id_grp_signal 

2. The second case, when an automation spams the api with a few messages too quickly.

That's what I've noticed related to :

{"error":"strconv.ParseInt: parsing \"INFO SignalAccount - Config file is in use by another instance, waiting…\\nINFO SignalAccount - Config file lock acquired.\\n1696717441700\": invalid syntax"}

[kxait]

It seems that this is not an issue with signal-cli-rest-api, but signal-cli... The culprit (at least for my issue, I can assume for OP's issue aswell) is that there are log messages sent on the INFO channel that break the expected output. The log configurator for signal-cli has a minimum loglevel of INFO and doesn't have filtering for when the output is expected to be JSON

lc.getLogger("org.asamk").setLevel(verboseLevel > 1 ? Level.ALL : verboseLevel > 0 ? Level.DEBUG : Level.INFO);

I think that in my case this was caused by a receive and send command running simulatenously (my application receives messages in a loop), so the lock was unavailable for a bit. signal-cli doesn't seem to have an option for excluding the logs from output entirely, only raising the log level... A workaround might be filtering signal-cli's output and excluding all lines that might signify they are log messages (e.g. starting with INFO). I'm going to submit a pr to signal-cli to change the logging behavior.

[bbernhard]

Yeah, that's exactly the issue. The workaround is what I've implemented now (if you want to give it a try, have a look at the pre-release from yesterday). But of course, that's just a hacky solution that might break at some point.

@kxait could you maybe let me know when the PR is merged? That would be great. Many thanks!

[bbernhard]

@kxait would it maybe possible to only strip log those messages from the stdout/stderr output, but still log them to a file? The signal-cli command line already has a flag which allows to log messages to a file, but unfortunately it still prints them to stdout/stderr. Not sure if that's something you can/want to tackle in your PR, but if you do, it would be greatly appreciated!

[kxait]

@bbernhard it seems the issue is actually here:

combinedOutput := stdoutBuffer.String() + stderrBuffer.String()

snip

all logs are printed to stderr, and in this case we're returning the combined output of stdout and stderr, a fix to this seems to actually be to only return stdout

[bbernhard]

@bbernhard it seems the issue is actually here:

combinedOutput := stdoutBuffer.String() + stderrBuffer.String()

snip

all logs are printed to stderr, and in this case we're returning the combined output of stdout and stderr, a fix to this seems to actually be to only return stdout

This was done on purpose (see https://github.com/bbernhard/signal-cli-rest-api/pull/404)

[kxait]

Right, so perhaps the actual fix would be for signal-cli to only log actual errors on stderr (if outputting json), skipping info and warn?

[bbernhard]

I think the info and warn messages are also important (as they are often an indication that something is not working as intended or is going to break in the future). But reliably parsing those messages in an automated way is a bit tricky and cumbersome.

I don't know the internals of signal-cli well enough, but what I would find great is, if there would be a commandline option that redirects that informational output to a log file. We could then expose the contents of that file via REST. So whenever there is a problem, we could tell people to have a look at that file first if there are some indications of whats going wrong.

What do you think about that? Do you think that makes sense?

[kxait]

Yes, that would make sense, but it would also require to break the fix for #403

I don't know the internals of signal-cli well enough, but what I would find great is, if there would be a commandline option that redirects that informational output to a log file

There is the --log-file option, and if we had an endpoint for the logfile we could just put everything there and go back before #403 where there was only stdout in the REST responses, then my PR for signal-cli could be closed unresolved.

[bbernhard]

Yes, that would make sense, but it would also require to break the fix for #403

I don't know the internals of signal-cli well enough, but what I would find great is, if there would be a commandline option that redirects that informational output to a log file

There is the --log-file option, and if we had an endpoint for the logfile we could just put everything there and go back before #403 where there was only stdout in the REST responses, then my PR for signal-cli could be closed unresolved.

yeah, you are right. That would work then.

@roschaefer would that be fine for you? I think it is a more robust solution than parsing the info and warn messages in the response data.

[roschaefer]

@bbernhard I don't have a strong opinion here as I haven't looked into this for a while.

Is the only problem that we don't escape a JSON injection? If so, couldn't we just do that? It should always be a good idea, not only for JSON but also for HTML, SQL etc.

[kxait]

Is the only problem that we don't escape a JSON injection? If so, couldn't we just do that? It should always be a good idea, not only for JSON but also for HTML, SQL etc.

not necessarily, some messages are received raw

{"error":"strconv.ParseInt: parsing \"INFO  SignalAccount - Config file is in use by another instance, waiting…\\nINFO  SignalAccount - Config file lock acquired.\\n1696717441700\": invalid syntax"}

@bbernhard perhaps instead of an endpoint for the log file, we could include optional additionalInfo in every response, redirecting stderr there, activated by a query (or body) param includeAdditionalInfo? an endpoint for the log file would mean getting the entire log file whenever you run into a case like #403, which could lead to performance issues and ambiguous formatting

[bbernhard]

Is the only problem that we don't escape a JSON injection? If so, couldn't we just do that? It should always be a good idea, not only for JSON but also for HTML, SQL etc.

not necessarily, some messages are received raw

{"error":"strconv.ParseInt: parsing \"INFO  SignalAccount - Config file is in use by another instance, waiting…\\nINFO  SignalAccount - Config file lock acquired.\\n1696717441700\": invalid syntax"}

@bbernhard perhaps instead of an endpoint for the log file, we could include optional additionalInfo in every response, redirecting stderr there, activated by a query (or body) param includeAdditionalInfo? an endpoint for the log file would mean getting the entire log file whenever you run into a case like #403, which could lead to performance issues and ambiguous formatting

Yeah, that sounds much nicer. Especially, as you get really meaningful information back from signal-cli, that most of the time is useful to one in the exact moment. Really like the idea! I would even make that not configureable and always return that information (or make it configureable and make the default true)

[kxait]

I would even make that not configureable and always return that information (or make it configureable and make the default true)

For some endpoints including additional information would introduce breaking changes:

• GET /v1/receive/{number} - currently returns an array of all received messages (lines from signal-cli output concatenated into an array), it would make sense to put this inside of an object like {messages: [...], additionalInfo: "..."}
• GET /v1/groups/{number} - same situation, currently we return an array, it would make sense to put this in an object
• GET /v1/qrcodelink - this returns an image/png which makes many things very simple for API consumers, not really sure how to include additionalInfo in here
• GET /v1/attachments - returns string

... and many more. Having the additional info hidden behind a param could change the response shape, in the case of /v1/receive from an array to an object.

It could be nice to have the additional info standardized across all responses and returning an object like {response: [...]/{...}/"...", additionalInfo: [...]} if a query param is provided.

Another idea I had is to discard stderr from the response completely if a query param like skip-info is provided. This would not break #403 and solve OP's issue with minimal impact. What do you think?