INFO message injected in JSON response

k-bx commented 1 year ago

The problem

266986826-9ee7c1d3-1124-46e5-aaa6-96cb1fafd317

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 commented 1 year ago

Thanks, I'll have a look!

kxait commented 12 months ago

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 commented 11 months ago

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 commented 11 months ago

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 commented 11 months ago

Hi @bbernhard @kxait,

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

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

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 commented 11 months ago

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 commented 11 months ago

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 commented 11 months ago

@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 commented 11 months ago

@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 commented 11 months ago

@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 commented 11 months ago

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 commented 11 months ago

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 commented 11 months ago

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 commented 11 months ago

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 commented 11 months ago

@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 commented 11 months ago

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 commented 11 months ago

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 commented 10 months ago

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?

bbernhard / signal-cli-rest-api