missing \n on (some) CPLDC messages?

[f00b4r0]

Hi,

(While testing a new antenna) I noticed the following output from dumpvdl2 (simultaneously on two separate machines running from different dongles - so probably not a fluke):

───┐
  │[2024-07-29 20:23:02 CEST] [136.975] [-19.1/-43.2 dBFS] [24.1 dB] [0.9 ppm]                                                                                                                                         │
  │406135 (Aircraft, Airborne) -> 10909A (Ground station): Command                                                                                                                                                     │
  │AVLC type: I sseq: 2 rseq: 3 poll: 0                                                                                                                                                                                │
[2│ X.25 Data: grp: 11 chan: 255 sseq: 0 rseq: 1 more: 0                                                                                                                                                               │
40│  X.25 reasm status: skipped                                                                                                                                                                                     │
AV│  X.233 CLNP Data (compressed header):                                                                                                                                                                              │
  │   LRef: 0x45 Prio: 11 Flags: 0xf6                                                                                                                                                                                  │
[2│   Lifetime: 20.0 sec                                                                                                                                                                                               │
40│   PDU Id: 0x1c4                                                                                                                                                                                                    │
AV│   X.224 COTP Data Ack:                                                                                                                                                                                             │
 X│    dst_ref: 0x6d3d                                                                                                                                                                                                 │
  │    rseq: 2 credit: 2                                                                                                                                                                                               │
  │    ATN checksum: 4b f3 14 49                                                                                                                                                                                       │
  │   X.224 COTP Data:                                                                                                                                                                                                 │
  │    dst_ref: 0x6d3d                                                                                                                                                                                                 │
  │    sseq: 1 req_of_ack: 0 EoT: 1                                                                                                                                                                                    │
  │    COTP reasm status: skipped                                                                                                                                                                                      │
  │    ATN checksum: 66 51 a3 6a                                                                                                                                                                                       │
[2│    CPDLC Downlink Message:                                                                                                                                                                                         │
40│     Header:                                                                                                                                                                                                        │
AV│      Msg ID: 1                                                                                                                                                                                                     │
 A│      Msg Ref: 1                                                                                                                                                                                                    │
  │      Timestamp: 2024-07-29 18:23:00                                                                                                                                                                                │
  │      Logical ACK: notRequired                                                                                                                                                                                      │
  │     Message data:                                                                                                                                                                                                  │
  │      ERROR                                                                                                                                                                                                         │
  │       Error information: insufficientResources                                                                                                                                                                     │
  │      FREE TEXT                                                                                                                                                                                                     │
  │       UPLINK DELAYED IN NETWORK AND REJECTED. RESEND OR CONTACT BY VOICE[2024-07-29 20:23:03 CEST] [136.975] [-19.2/-43.5 dBFS] [24.3 dB] [0.8

(This is a copy-paste from multitail backlog, hence the minor garbage at beginning of lines.)

The FREE TEXT message is apparently printed without a terminating newline, resulting in the header of the next frame being appended to the message.

I tried looking into the code to fix this but eventually got lost in all the levels of print/formatting indirections and gave up. I hope this provides enough info to locate the problem though. I think this bug lies in libacars, hence opening the issue here.

HTH

[szpajder]

All CPDLC downlink messages with a "FREE TEXT" label are mapped to a FreeText_t type (see ATCDownlinkMsgElementId.h#L248 and further down). This type is an alias to IA5String_t (FreeText.h#L22) which in turn is an alias to OCTET_STRING_t (IA5String.h#L14). This type has a type descriptor object named asn_DEF_OCTET_STRING (OCTET_STRING.h#L21). Object of this type are stringified using la_asn1_format_any_as_text function (asn1-format-icao-text.c#L1293) which is defined at asn1-format-common.c#L300. As you see, it unconditionally adds a terminating newline using LA_EOL macro.

dumpvdl2 prints decoded text output to files using out_file_produce_text function which unconditionally adds a terminating newline after each message (output-file.c#L172).

Hence, I can't come up with any scenario which would cause these newlines to be omitted. I've also grepped all my log files collected this and last year and have found no such occurrences. Are you logging messages to files? Does the output look the same in the file or only in multitail? Maybe the output got corrupted by multitail or the terminal? If the problem is real, I need a raw message log produced either with --output raw:binary:file:... or --raw-frames to reproduce this.

[f00b4r0]

All CPDLC downlink messages with a "FREE TEXT" label are mapped to a FreeText_t type (see ATCDownlinkMsgElementId.h#L248 and further down). This type is an alias to IA5String_t (FreeText.h#L22) which in turn is an alias to OCTET_STRING_t (IA5String.h#L14). This type has a type descriptor object named asn_DEF_OCTET_STRING (OCTET_STRING.h#L21). Object of this type are stringified using la_asn1_format_any_as_text function (asn1-format-icao-text.c#L1293) which is defined at asn1-format-common.c#L300. As you see, it unconditionally adds a terminating newline using LA_EOL macro.

dumpvdl2 prints decoded text output to files using out_file_produce_text function which unconditionally adds a terminating newline after each message (output-file.c#L172).

Thanks for the code walkout, it's helpful.

Hence, I can't come up with any scenario which would cause these newlines to be omitted. I've also grepped all my log files collected this and last year and have found no such occurrences. Are you logging messages to files? Does the output look the same in the file or only in multitail? Maybe the output got corrupted by multitail or the terminal? If the problem is real, I need a raw message log produced either with --output raw:binary:file:... or --raw-frames to reproduce this.

Indeed both occurrences happened with dumpvdl2 running within multitail, and both from the same terminal software (one over SSH, the other local), and I've seen it only once as reported above. One thing that should rule out terminal corruption though is that as you can see from the report, the "corrupted" output is visible in multitail backlog: that's really what told me I hadn't a cross-eyed moment :). Maybe it was indeed a multitail bug then and if you've never seen this in your year-long logfiles I think it's safe to ignore this report, so I'm closing it. Sorry for the noise.

[f00b4r0]

Purely FYI it just happened again as I was randomly taking a look at the output (still piped through multitail, running with --dump-asn1 enabled this time). Incidentally, the message that triggered the problem was exactly the same one: UPLINK DELAYED IN NETWORK AND REJECTED. RESEND OR CONTACT BY VOICE.
I should mention I'm using the dumpvdl2-provided multitail-dumpvdl2.conf.
Cheers

  ┌──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
  │[2024-08-20 09:19:58.705 GMT] [136.975] [-10.2/-43.1 dBFS] [32.9 dB] [-1.7 ppm] [S:0] [L:126] [F:0] [#0]                                                                                          │
  │39D2A7 (Aircraft, Airborne) -> 262259 (Ground station): Command                                                                                                                                   │
  │AVLC type: I sseq: 2 rseq: 2 poll: 0                                                                                                                                                              │
  │ X.25 Data: grp: 11 chan: 255 sseq: 5 rseq: 7 more: 0                                                                                                                                             │
  │  X.25 reasm status: skipped                                                                                                                                                                      │
  │  X.233 CLNP Data (compressed header):                                                                                                                                                            │
  │   LRef: 0x1 Prio: 11 Flags: 0xf6                                                                                                                                                                 │
  │   Lifetime: 32.0 sec                                                                                                                                                                             │
  │   PDU Id: 0x62                                                                                                                                                                                   │
  │   X.224 COTP Data Ack:                                                                                                                                                                           │
  │    dst_ref: 0xbc7d                                                                                                                                                                               │
  │    rseq: 2 credit: 2                                                                                                                                                                             │
[2│    ATN checksum: f6 7a 1c 72                                                                                                                                                                     │
40│   X.224 COTP Data:                                                                                                                                                                               │
AV│    dst_ref: 0xbc7d                                                                                                                                                                               │
  │    sseq: 1 req_of_ack: 0 EoT: 1                                                                                                                                                                  │  
[2│    COTP reasm status: skipped                                                                                                                                                                    │
40│    ATN checksum: 76 3c 5e 5f                                                                                                                                                                     │
AV│    ASN.1 dump:                                                                                                                                                                                   │
 X│     ATCDownlinkMessage ::= {                                                                                                                                                                     │
  │      header: ATCMessageHeader ::= {                                                                                                                                                              │
  │       messageIdNumber: 1                                                                                                                                                                         │
  │       messageRefNumber: 1                                                                                                                                                                        │
  │       dateTime: DateTimeGroup ::= {                                                                                                                                                              │
  │        date: Date ::= {                                                                                                                                                                          │
  │         year: 2024                                                                                                                                                                               │
  │         month: 8                                                                                                                                                                                 │
[2│         day: 20                                                                                                                                                                                  │  
34│        }                                                                                                                                                                                         │
AV│        timehhmmss: Timehhmmss ::= {                                                                                                                                                              │
 X│         hoursminutes: Time ::= {                                                                                                                                                                 │
  │          hours: 9                                                                                                                                                                                │
  │          minutes: 19                                                                                                                                                                             │
  │         }                                                                                                                                                                                        │
  │         seconds: 57                                                                                                                                                                              │
  │        }                                                                                                                                                                                         │
  │       }                                                                                                                                                                                          │
  │       logicalAck: 1                                                                                                                                                                              │
  │      }                                                                                                                                                                                           │
  │      messageData: ATCDownlinkMessageData ::= {                                                                                                                                                   │
  │       elementIds: ATCDownlinkMsgElementIdSequence ::= {                                                                                                                                          │
AV│        dM62ErrorInformation: 2                                                                                                                                                                   │
  │        dM98FreeText: UPLINK DELAYED IN NETWORK AND REJECTED. RESEND OR CONTACT BY VOICE[2024-08-20 09:19:59.156 GMT] [136.675] [-8.6/-41.8 dBFS] [33.1 dB] [0.1 ppm] [S:0] [L:14] [F:0] [#0]     │
[2│4CA8D9 (Aircraft, Airborne) -> 109F5A (Ground station): Response                                                                                                                                  │

[f00b4r0]

and one more, maybe related, datapoint: running dumpvdl2 --extended-header --dump-asn1 --utc --milliseconds --output decode:text:file:path=- | grep -A1 " dBFS" (to do a quick survey of reception quality), after a (long) while I suddenly stopped getting any output from grep even though dumpvdl2 was still working just fine (feeding over UDP). Output ended with:

--
[2024-08-23 13:25:29.115 GMT] [136.875] [-11.7/-43.7 dBFS] [32.0 dB] [-1.7 ppm] [S:0] [L:42] [F:0] [#0]
3986EC (Aircraft, Airborne) -> 2190E2 (Ground station): Command
grep: (standard input): binary file matches

No multitail involved here (only screen, in fact).

This grep response (and end of output) can typically be caused by null bytes in the output stream: I'm not sure dumpvdl2 is supposed to put out any in decoded:text mode (that would seem rather odd in this case), so I think something is amiss here, hence reopening this issue.

FWIW a null byte that "eats" the expected "\n" could certainly cause the situation reported in the first post.

HTH